-- Logs begin at Mon 2025-07-07 08:44:53 CST, end at Mon 2025-07-07 19:07:12 CST. -- Jul 07 19:06:05 volumio nmbd[521]: [2025/07/07 19:06:05.293516, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Jul 07 19:06:05 volumio nmbd[521]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.66.21 for name WORKGROUP<1d>. Jul 07 19:06:05 volumio nmbd[521]: This response was from IP 192.168.66.97, reporting an IP address of 192.168.66.97. Jul 07 19:06:28 volumio volumio[808]: info: Received OAUTH Data Jul 07 19:06:28 volumio volumio[808]: info: Executing Spotify Oauth Login Jul 07 19:06:28 volumio volumio[808]: info: Saving Spotify Refresh Token Jul 07 19:06:29 volumio sudo[23078]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 07 19:06:29 volumio sudo[23078]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 07 19:06:29 volumio volumio[808]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 07 19:06:29 volumio volumio[808]: SPOTIFY: BQCowa-U-wjLwHE9tkSghlqtMgadHMftRwRgOQHtbd3i_ya2IOnTb9SHbDLgQBqsu2WKwRM4IlEH_abizlRSvKYM-6K-cxu_GXyCIsmSAD1DCaLFsALsweHPv0jLOd-kndbzAINwtnVRyqvLh79Ya5mbkf5iRzpdqSMXULj8bGztABQf4S5RvfWzA3uKPdp2aLMSkU0e8BKqcXq6ZKLuvyqUFw0euEToLSmqD7ayEZL3TcBacs-TgBQa1a7T_bf5Kdx3RfjPYWWg9uYyPWN5Xe-of2A Jul 07 19:06:29 volumio volumio[808]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 07 19:06:29 volumio volumio[808]: info: New Spotify access token = BQCowa-U-wjLwHE9tkSghlqtMgadHMftRwRgOQHtbd3i_ya2IOnTb9SHbDLgQBqsu2WKwRM4IlEH_abizlRSvKYM-6K-cxu_GXyCIsmSAD1DCaLFsALsweHPv0jLOd-kndbzAINwtnVRyqvLh79Ya5mbkf5iRzpdqSMXULj8bGztABQf4S5RvfWzA3uKPdp2aLMSkU0e8BKqcXq6ZKLuvyqUFw0euEToLSmqD7ayEZL3TcBacs-TgBQa1a7T_bf5Kdx3RfjPYWWg9uYyPWN5Xe-of2A Jul 07 19:06:29 volumio volumio[808]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 07 19:06:29 volumio sudo[23080]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 07 19:06:29 volumio sudo[23078]: pam_unix(sudo:session): session closed for user root Jul 07 19:06:29 volumio sudo[23080]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 07 19:06:29 volumio sudo[23080]: pam_unix(sudo:session): session closed for user root Jul 07 19:06:29 volumio volumio[808]: verbose: New Socket.io Connection to 192.168.66.21 from 192.168.66.13 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/137.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::volumioGetVisibleSources Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:29 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 07 19:06:29 volumio volumio[808]: info: Received Get System Info Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 07 19:06:29 volumio volumio[808]: info: Discovery: Getting this device information Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:29 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:29 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:29 volumio volumio[808]: info: Listing playlists Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jul 07 19:06:29 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 07 19:06:30 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jul 07 19:06:30 volumio volumio[808]: SPOTIFY: User informations: {"country":"TW","display_name":"pplovebobo","email":"sorine@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/pplovebobo"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/pplovebobo","id":"pplovebobo","images":[],"product":"premium","type":"user","uri":"spotify:user:pplovebobo"} Jul 07 19:06:30 volumio volumio[808]: info: Creating Spotify config file Jul 07 19:06:30 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 07 19:06:30 volumio volumio[808]: info: Spotify config file written Jul 07 19:06:30 volumio sudo[23088]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 07 19:06:30 volumio sudo[23088]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 07 19:06:30 volumio systemd[1]: Stopping go-librespot Daemon... Jul 07 19:06:30 volumio volumio[808]: info: Connection to go-librespot Websocket closed Jul 07 19:06:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jul 07 19:06:30 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jul 07 19:06:30 volumio systemd[1]: Stopped go-librespot Daemon. Jul 07 19:06:30 volumio systemd[1]: Started go-librespot Daemon. Jul 07 19:06:30 volumio sudo[23088]: pam_unix(sudo:session): session closed for user root Jul 07 19:06:31 volumio volumio[808]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 07 19:06:31 volumio volumio[808]: SPOTIFY: BQDi5nEVEOi5bYLGznZI3q8RDlO9LqiFBnMUSIckfi3u1ko6CYcbtZ_NZiMoF5sEEf97Avf4WdLOwUBCaU48uZjZDvfrHcTY5yajHHzFxDSbSL-8JSR2X1rZhAvP8KN_Lfn4V9nThTSA_A78S2sgoUNq9Qj9afLP_VAtZDI_qZuU2R_dd3J83NBxgCGv9kd4JmPFOYWY7uqrUA4YvmTrDh6gn4Zx80nKD-bv2oAHWEGZHCpTgkPkiqY1PdX8wDdqJZIdXqSXpRbJv6BEc5JnQ5w-DyI Jul 07 19:06:31 volumio volumio[808]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 07 19:06:31 volumio volumio[808]: info: New Spotify access token = BQDi5nEVEOi5bYLGznZI3q8RDlO9LqiFBnMUSIckfi3u1ko6CYcbtZ_NZiMoF5sEEf97Avf4WdLOwUBCaU48uZjZDvfrHcTY5yajHHzFxDSbSL-8JSR2X1rZhAvP8KN_Lfn4V9nThTSA_A78S2sgoUNq9Qj9afLP_VAtZDI_qZuU2R_dd3J83NBxgCGv9kd4JmPFOYWY7uqrUA4YvmTrDh6gn4Zx80nKD-bv2oAHWEGZHCpTgkPkiqY1PdX8wDdqJZIdXqSXpRbJv6BEc5JnQ5w-DyI Jul 07 19:06:31 volumio volumio[808]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 07 19:06:31 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 07 19:06:31 volumio volumio[808]: info: Received Get System Info Jul 07 19:06:31 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 07 19:06:31 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 07 19:06:31 volumio volumio[808]: info: Discovery: Getting this device information Jul 07 19:06:31 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:31 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:31 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 07 19:06:31 volumio go-librespot[23090]: go-librespot daemon starting... Jul 07 19:06:31 volumio volumio[808]: SPOTIFY: User informations: {"country":"TW","display_name":"pplovebobo","email":"sorine@hotmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/pplovebobo"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/pplovebobo","id":"pplovebobo","images":[],"product":"premium","type":"user","uri":"spotify:user:pplovebobo"} Jul 07 19:06:31 volumio volumio[808]: info: Spotify Successfully logged in Jul 07 19:06:31 volumio volumio[808]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 07 19:06:31 volumio volumio[808]: info: [1751886391422] CoreMusicLibrary::Adding element Spotify Jul 07 19:06:31 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 07 19:06:31 volumio go-librespot[23090]: time="2025-07-07T19:06:31+08:00" level=info msg="running go-librespot 0.2.0" Jul 07 19:06:31 volumio volumio[808]: Cannot find translation for source Spotify Jul 07 19:06:31 volumio go-librespot[23090]: time="2025-07-07T19:06:31+08:00" level=debug msg="app state loaded" Jul 07 19:06:31 volumio go-librespot[23090]: time="2025-07-07T19:06:31+08:00" level=debug msg="stored credentials not found" Jul 07 19:06:31 volumio go-librespot[23090]: time="2025-07-07T19:06:31+08:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 07 19:06:31 volumio volumio[808]: info: An error occurred while initializing Spotify Browsing facility: TypeError: Cannot read property 'broadcastMessage' of null Jul 07 19:06:31 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jul 07 19:06:32 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 07 19:06:32 volumio volumio[808]: info: Received Get System Info Jul 07 19:06:32 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 07 19:06:32 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 07 19:06:32 volumio volumio[808]: info: Discovery: Getting this device information Jul 07 19:06:32 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:32 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:32 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=info msg="zeroconf server listening on port 44251" Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=debug msg="obtained new client token: AABmCBf123U67t+pfIWDuQF5enpbsJoNP33YIEAjYRn3DE7auIqtvnYA6aJ7Q6wDG2iwaS3LsR3d5pSrARSucC20zIdIRdLR/goLHHK/oGafgkl8bxlNfd2pq6PVy7NO07KUVRaDGrTJV2slTjyqduBtKZ0cZB1CxmfX0PwkdVr7CKRC8OlRaY2v2RKZn27HhfWKt9niOsx1azqMeDyM3TaXVzR8VxcZmT190jnv1urPuRx2IEO1IE46mQ==" Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=debug msg="completed keyexchange" Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=debug msg="completed challenge" Jul 07 19:06:33 volumio volumio[808]: info: Initializing connection to go-librespot Websocket Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=debug msg="new websocket client" Jul 07 19:06:33 volumio volumio[808]: info: Connection to go-librespot Websocket established Jul 07 19:06:33 volumio go-librespot[23090]: time="2025-07-07T19:06:33+08:00" level=info msg="authenticated AP as pplovebobo" Jul 07 19:06:33 volumio volumio[808]: info: go-librespot daemon successfully initialized Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=info msg="authenticated Login5 as pplovebobo" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="stored credentials for pplovebobo" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="initializing zeroconf session, username: pplovebobo" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="dealer connection opened" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=trace msg="starting accesspoint recv loop" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=trace msg="starting dealer recv loop" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=trace msg="received accesspoint ping" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="received connection id: M2U2MTA2MGUtMjQzOS00YzUwLWJmNDktMWZiNmYxNjgxYWVmK2RlYWxlcit0Y3A6Ly8wYWIxNTgwNi5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArNDgzMzU4NEI1MkJCODc5NjA0MEUzQkMwQzYwQUM1RDEyRkYwNTNEMDM4NUJFRUE5NkRCMENFODc2ODk5QkU0Rg==" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=trace msg="received accesspoint pong ack" Jul 07 19:06:34 volumio go-librespot[23090]: time="2025-07-07T19:06:34+08:00" level=debug msg="put connect state because NEW_DEVICE" Jul 07 19:06:36 volumio volumio[808]: info: Getting Spotify volume Jul 07 19:06:36 volumio volumio[808]: info: Spotify volume: 100 Jul 07 19:06:36 volumio volumio[808]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jul 07 19:06:36 volumio volumio[808]: info: Initializing connection to go-librespot Websocket Jul 07 19:06:37 volumio go-librespot[23090]: time="2025-07-07T19:06:37+08:00" level=debug msg="new websocket client" Jul 07 19:06:37 volumio volumio[808]: info: Connection to go-librespot Websocket established Jul 07 19:06:37 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:37 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:37 volumio volumio[808]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 07 19:06:37 volumio volumio[808]: SPOTIFY: SPOTIFY VOLUME 100 Jul 07 19:06:37 volumio volumio[808]: SPOTIFY: VOLUMIO VOLUME 46 Jul 07 19:06:37 volumio volumio[808]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 07 19:06:37 volumio volumio[808]: info: Setting Spotify Volume from Volumio: 46 Jul 07 19:06:38 volumio volumio[808]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Jul 07 19:06:38 volumio volumio[808]: info: Sending Spotify command with payload to local API: /player/volume Jul 07 19:06:38 volumio go-librespot[23090]: time="2025-07-07T19:06:38+08:00" level=debug msg="update volume to 30146/65535" Jul 07 19:06:39 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jul 07 19:06:39 volumio go-librespot[23090]: time="2025-07-07T19:06:39+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 07 19:06:39 volumio go-librespot[23090]: time="2025-07-07T19:06:39+08:00" level=trace msg="emitting websocket event: volume" Jul 07 19:06:39 volumio volumio[808]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Jul 07 19:06:39 volumio volumio[808]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Jul 07 19:06:39 volumio volumio[808]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Jul 07 19:06:39 volumio volumio[808]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Jul 07 19:06:40 volumio volumio[808]: info: Getting Spotify volume Jul 07 19:06:40 volumio volumio[808]: info: Spotify volume: 46 Jul 07 19:06:40 volumio volumio[808]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jul 07 19:06:40 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:40 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:40 volumio volumio[808]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 07 19:06:47 volumio volumio[808]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jul 07 19:06:47 volumio volumio[808]: info: Creating Spotify config file Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 07 19:06:47 volumio volumio[808]: info: Spotify config file written Jul 07 19:06:47 volumio sudo[23158]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 07 19:06:47 volumio sudo[23158]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 07 19:06:47 volumio volumio[808]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jul 07 19:06:47 volumio volumio[808]: error: Failed callmethod call: TypeError: Cannot read property 'broadcastMessage' of null Jul 07 19:06:47 volumio volumio[808]: info: Received Get System Version Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 07 19:06:47 volumio volumio[808]: info: Received Get System Info Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 07 19:06:47 volumio volumio[808]: info: Discovery: Getting this device information Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:47 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:47 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 07 19:06:47 volumio systemd[1]: Stopping go-librespot Daemon... Jul 07 19:06:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jul 07 19:06:47 volumio volumio[808]: info: Connection to go-librespot Websocket closed Jul 07 19:06:47 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jul 07 19:06:47 volumio systemd[1]: Stopped go-librespot Daemon. Jul 07 19:06:47 volumio volumio[808]: info: Connection to go-librespot Websocket closed Jul 07 19:06:47 volumio systemd[1]: Started go-librespot Daemon. Jul 07 19:06:47 volumio sudo[23158]: pam_unix(sudo:session): session closed for user root Jul 07 19:06:47 volumio go-librespot[23162]: go-librespot daemon starting... Jul 07 19:06:47 volumio go-librespot[23162]: time="2025-07-07T19:06:47+08:00" level=info msg="running go-librespot 0.2.0" Jul 07 19:06:47 volumio go-librespot[23162]: time="2025-07-07T19:06:47+08:00" level=debug msg="app state loaded" Jul 07 19:06:47 volumio go-librespot[23162]: time="2025-07-07T19:06:47+08:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 07 19:06:48 volumio go-librespot[23162]: time="2025-07-07T19:06:48+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 07 19:06:48 volumio go-librespot[23162]: time="2025-07-07T19:06:48+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jul 07 19:06:48 volumio go-librespot[23162]: time="2025-07-07T19:06:48+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jul 07 19:06:48 volumio go-librespot[23162]: time="2025-07-07T19:06:48+08:00" level=info msg="zeroconf server listening on port 36053" Jul 07 19:06:48 volumio go-librespot[23162]: time="2025-07-07T19:06:48+08:00" level=debug msg="obtained new client token: AADw3HJ9ed3TmTnpCziYgr6q5iSKqfvrjitcl+Oqt4cCA3l4ZetByAojpPkmcpvI7fWBznQqYspJ1+faWVqyStXjWVZgSFnmV99NZeY/td7IsCvjdCdkXHj2OPr8TdGxHWIbvtKR4oWTTtQUJzEuPDC5/NTflKeWVxbxPjtd+q4wNtWEs7SRHka/68W8Ec3IpoMSyS556dU3Q3comxICRKyUe4XNxO6fBODAAcyy1Qwrkxhtmldnh7xWLg==" Jul 07 19:06:48 volumio go-librespot[23162]: time="2025-07-07T19:06:48+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jul 07 19:06:48 volumio go-librespot[23162]: time="2025-07-07T19:06:48+08:00" level=debug msg="completed keyexchange" Jul 07 19:06:48 volumio go-librespot[23162]: time="2025-07-07T19:06:48+08:00" level=debug msg="completed challenge" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=info msg="authenticated AP as pplovebobo" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=info msg="authenticated Login5 as pplovebobo" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="initializing zeroconf session, username: pplovebobo" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="dealer connection opened" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=trace msg="starting accesspoint recv loop" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=trace msg="starting dealer recv loop" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=trace msg="received accesspoint ping" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="received connection id: YTZiZmQxYmQtNWI1NC00ZjM0LWFlMGUtYjlkYzE0ZTAzNTM0K2RlYWxlcit0Y3A6Ly8wYWIxNTg1YS5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArNUZGQUE3QkI3MDI1NkZFM0U0NjA0MjI4RDg5MTg4MzE4QzAyQzZENEY1NUFFRjBDRjQyNzcxQUExMzYwN0IwRA==" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=trace msg="received accesspoint pong ack" Jul 07 19:06:49 volumio go-librespot[23162]: time="2025-07-07T19:06:49+08:00" level=debug msg="put connect state because NEW_DEVICE" Jul 07 19:06:50 volumio volumio[808]: info: Initializing connection to go-librespot Websocket Jul 07 19:06:50 volumio go-librespot[23162]: time="2025-07-07T19:06:50+08:00" level=debug msg="new websocket client" Jul 07 19:06:50 volumio volumio[808]: info: Connection to go-librespot Websocket established Jul 07 19:06:50 volumio volumio[808]: info: go-librespot daemon successfully initialized Jul 07 19:06:53 volumio volumio[808]: info: Getting Spotify volume Jul 07 19:06:53 volumio volumio[808]: info: Spotify volume: 100 Jul 07 19:06:53 volumio volumio[808]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jul 07 19:06:53 volumio volumio[808]: info: Initializing connection to go-librespot Websocket Jul 07 19:06:53 volumio go-librespot[23162]: time="2025-07-07T19:06:53+08:00" level=debug msg="new websocket client" Jul 07 19:06:53 volumio volumio[808]: info: Connection to go-librespot Websocket established Jul 07 19:06:53 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:53 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:53 volumio volumio[808]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 07 19:06:53 volumio volumio[808]: SPOTIFY: SPOTIFY VOLUME 100 Jul 07 19:06:53 volumio volumio[808]: SPOTIFY: VOLUMIO VOLUME 46 Jul 07 19:06:53 volumio volumio[808]: SPOTIFY: DELTA VOLUME ENOUGH: true Jul 07 19:06:53 volumio volumio[808]: info: Setting Spotify Volume from Volumio: 46 Jul 07 19:06:55 volumio volumio[808]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Jul 07 19:06:55 volumio volumio[808]: info: Sending Spotify command with payload to local API: /player/volume Jul 07 19:06:55 volumio go-librespot[23162]: time="2025-07-07T19:06:55+08:00" level=debug msg="update volume to 30146/65535" Jul 07 19:06:56 volumio go-librespot[23162]: time="2025-07-07T19:06:56+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 07 19:06:56 volumio go-librespot[23162]: time="2025-07-07T19:06:56+08:00" level=trace msg="emitting websocket event: volume" Jul 07 19:06:56 volumio volumio[808]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Jul 07 19:06:56 volumio volumio[808]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Jul 07 19:06:56 volumio volumio[808]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Jul 07 19:06:56 volumio volumio[808]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Jul 07 19:06:56 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:56 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:56 volumio volumio[808]: info: Getting Spotify volume Jul 07 19:06:56 volumio volumio[808]: info: Spotify volume: 46 Jul 07 19:06:56 volumio volumio[808]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jul 07 19:06:56 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:06:56 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:06:56 volumio volumio[808]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 07 19:07:02 volumio volumio[808]: info: CoreCommandRouter::volumioGetQueue Jul 07 19:07:02 volumio volumio[808]: info: CoreStateMachine::getQueue Jul 07 19:07:02 volumio volumio[808]: info: CorePlayQueue::getQueue Jul 07 19:07:04 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:07:04 volumio volumio[808]: info: CorePlayQueue::getTrack 0 Jul 07 19:07:04 volumio volumio[808]: info: Prefetching next song Jul 07 19:07:04 volumio volumio[808]: info: DOING PREFETCH IN MPD Jul 07 19:07:04 volumio volumio[808]: verbose: ControllerMpd::sendMpdCommand add "INTERNAL/[230412] TVアニメ『【推しの子】』OP「アイドル」FLAC+MP3/01. アイドル.flac" Jul 07 19:07:04 volumio volumio[808]: info: sendMpdCommand add "INTERNAL/[230412] TVアニメ『【推しの子】』OP「アイドル」FLAC+MP3/01. アイドル.flac" took 18 milliseconds Jul 07 19:07:04 volumio volumio[808]: verbose: ControllerMpd::sendMpdCommand consume 1 Jul 07 19:07:04 volumio volumio[808]: info: Jul 07 19:07:04 volumio volumio[808]: ---------------------------- MPD announces system playlist update Jul 07 19:07:04 volumio volumio[808]: info: Ignoring MPD Status Update Jul 07 19:07:04 volumio volumio[808]: info: Jul 07 19:07:04 volumio volumio[808]: ---------------------------- MPD announces system playlist update Jul 07 19:07:04 volumio volumio[808]: info: Ignoring MPD Status Update Jul 07 19:07:04 volumio volumio[808]: info: Jul 07 19:07:04 volumio volumio[808]: ---------------------------- MPD announces system playlist update Jul 07 19:07:04 volumio volumio[808]: info: Ignoring MPD Status Update Jul 07 19:07:04 volumio volumio[808]: info: Jul 07 19:07:04 volumio volumio[808]: ---------------------------- MPD announces system playlist update Jul 07 19:07:04 volumio volumio[808]: info: Ignoring MPD Status Update Jul 07 19:07:04 volumio volumio[808]: info: sendMpdCommand consume 1 took 43 milliseconds Jul 07 19:07:04 volumio volumio[808]: info: ------------------------------ 46ms Jul 07 19:07:04 volumio volumio[808]: info: ------------------------------ 44ms Jul 07 19:07:04 volumio volumio[808]: info: ------------------------------ 31ms Jul 07 19:07:04 volumio volumio[808]: info: ------------------------------ 33ms Jul 07 19:07:07 volumio volumio[808]: info: CoreCommandRouter::volumioGetState Jul 07 19:07:07 volumio volumio[808]: info: CorePlayQueue::getTrack 1 Jul 07 19:07:08 volumio volumio[808]: info: CoreStateMachine::startPlaybackTimer Jul 07 19:07:08 volumio volumio[808]: info: CorePlayQueue::getTrack 0 Jul 07 19:07:08 volumio volumio[808]: info: Jul 07 19:07:08 volumio volumio[808]: ---------------------------- MPD announces system playlist update Jul 07 19:07:08 volumio volumio[808]: info: Ignoring MPD Status Update Jul 07 19:07:08 volumio volumio[808]: info: Jul 07 19:07:08 volumio volumio[808]: ---------------------------- MPD announces state update: player Jul 07 19:07:08 volumio volumio[808]: info: ControllerMpd::getState Jul 07 19:07:08 volumio volumio[808]: verbose: ControllerMpd::sendMpdCommand status Jul 07 19:07:08 volumio volumio[808]: info: Jul 07 19:07:08 volumio volumio[808]: ---------------------------- MPD announces system playlist update Jul 07 19:07:08 volumio volumio[808]: info: Ignoring MPD Status Update Jul 07 19:07:08 volumio volumio[808]: info: Jul 07 19:07:08 volumio volumio[808]: ---------------------------- MPD announces state update: player Jul 07 19:07:08 volumio volumio[808]: info: ControllerMpd::getState Jul 07 19:07:08 volumio volumio[808]: verbose: ControllerMpd::sendMpdCommand status Jul 07 19:07:08 volumio volumio[808]: info: Jul 07 19:07:08 volumio volumio[808]: ---------------------------- MPD announces system playlist update Jul 07 19:07:08 volumio volumio[808]: info: Ignoring MPD Status Update Jul 07 19:07:08 volumio volumio[808]: info: Jul 07 19:07:08 volumio volumio[808]: ---------------------------- MPD announces state update: player Jul 07 19:07:08 volumio volumio[808]: info: ControllerMpd::getState Jul 07 19:07:08 volumio volumio[808]: verbose: ControllerMpd::sendMpdCommand status Jul 07 19:07:08 volumio volumio[808]: info: Jul 07 19:07:08 volumio volumio[808]: ---------------------------- MPD announces system playlist update Jul 07 19:07:08 volumio volumio[808]: info: Ignoring MPD Status Update Jul 07 19:07:08 volumio volumio[808]: info: Jul 07 19:07:08 volumio volumio[808]: ---------------------------- MPD announces state update: player Jul 07 19:07:08 volumio volumio[808]: info: ControllerMpd::getState Jul 07 19:07:08 volumio volumio[808]: verbose: ControllerMpd::sendMpdCommand status Jul 07 19:07:09 volumio volumio[808]: info: CoreStateMachine::pushState Jul 07 19:07:09 volumio volumio[808]: info: CorePlayQueue::getTrack 0 Jul 07 19:07:09 volumio volumio[808]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 07 19:07:09 volumio volumio[808]: info: CoreCommandRouter::volumioPushState Jul 07 19:07:09 volumio volumio[808]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 07 19:07:09 volumio volumio[808]: TypeError: Cannot read property 'pushState' of null Jul 07 19:07:09 volumio volumio[808]: at /volumio/app/index.js:326:32 Jul 07 19:07:09 volumio volumio[808]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Jul 07 19:07:09 volumio volumio[808]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Jul 07 19:07:09 volumio volumio[808]: at CoreCommandRouter.volumioPushState (/volumio/app/index.js:324:13) Jul 07 19:07:09 volumio volumio[808]: at CoreStateMachine.pushState (/volumio/app/statemachine.js:532:22) Jul 07 19:07:09 volumio volumio[808]: at listOnTimeout (internal/timers.js:554:17) Jul 07 19:07:09 volumio volumio[808]: at processTimers (internal/timers.js:497:7) Jul 07 19:07:09 volumio volumio[808]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 07 19:07:12 volumio sudo[23287]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-07 19:06 Jul 07 19:07:12 volumio sudo[23287]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 02 Jul 2025 04:07:25 PM CEST" VOLUMIO_VERSION="3.819" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3b9115b1943141a9d7186aa434f8f3c2"