-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Sun 2025-06-22 11:40:13 CST. -- Jun 22 11:39:06 volumio sshd[6111]: Accepted password for volumio from 192.168.0.88 port 38980 ssh2 Jun 22 11:39:06 volumio sshd[6111]: pam_unix(sshd:session): session opened for user volumio by (uid=0) Jun 22 11:39:06 volumio systemd[1]: Created slice User Slice of UID 1000. Jun 22 11:39:06 volumio systemd[1]: Starting User Runtime Directory /run/user/1000... Jun 22 11:39:06 volumio systemd-logind[546]: New session 3 of user volumio. Jun 22 11:39:06 volumio systemd[1]: Started User Runtime Directory /run/user/1000. Jun 22 11:39:06 volumio systemd[1]: Starting User Manager for UID 1000... Jun 22 11:39:06 volumio systemd[6116]: pam_unix(systemd-user:session): session opened for user volumio by (uid=0) Jun 22 11:39:06 volumio systemd[6116]: Reached target Timers. Jun 22 11:39:06 volumio systemd[6116]: Starting D-Bus User Message Bus Socket. Jun 22 11:39:06 volumio systemd[6116]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers). Jun 22 11:39:06 volumio systemd[6116]: Listening on Sound System. Jun 22 11:39:06 volumio systemd[6116]: Reached target Paths. Jun 22 11:39:06 volumio systemd[6116]: Listening on GnuPG cryptographic agent (ssh-agent emulation). Jun 22 11:39:06 volumio systemd[6116]: Listening on GnuPG cryptographic agent and passphrase cache (restricted). Jun 22 11:39:06 volumio systemd[6116]: Listening on GnuPG cryptographic agent and passphrase cache. Jun 22 11:39:06 volumio systemd[6116]: Listening on GnuPG network certificate management daemon. Jun 22 11:39:06 volumio systemd[6116]: Listening on D-Bus User Message Bus Socket. Jun 22 11:39:06 volumio systemd[6116]: Reached target Sockets. Jun 22 11:39:06 volumio systemd[6116]: Reached target Basic System. Jun 22 11:39:06 volumio systemd[6116]: Reached target Default. Jun 22 11:39:06 volumio systemd[6116]: Startup finished in 229ms. Jun 22 11:39:06 volumio systemd[1]: Started User Manager for UID 1000. Jun 22 11:39:06 volumio systemd[1]: Started Session 3 of user volumio. Jun 22 11:39:15 volumio sudo[6154]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl sop bridge-input Jun 22 11:39:15 volumio sudo[6154]: pam_unix(sudo:session): session opened for user root by volumio(uid=0) Jun 22 11:39:15 volumio sudo[6154]: pam_unix(sudo:session): session closed for user root Jun 22 11:39:19 volumio sudo[6170]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl stop bridge-input Jun 22 11:39:19 volumio sudo[6170]: pam_unix(sudo:session): session opened for user root by volumio(uid=0) Jun 22 11:39:19 volumio sh[2448]: Aborted by signal Terminated... Jun 22 11:39:19 volumio sh[2448]: Aborted by signal Terminated... Jun 22 11:39:19 volumio systemd[1]: Stopping Pipe audio input into volumio output device with low latency... Jun 22 11:39:19 volumio systemd[1]: bridge-input.service: Main process exited, code=killed, status=15/TERM Jun 22 11:39:19 volumio systemd[1]: bridge-input.service: Succeeded. Jun 22 11:39:19 volumio systemd[1]: Stopped Pipe audio input into volumio output device with low latency. Jun 22 11:39:19 volumio sudo[6170]: pam_unix(sudo:session): session closed for user root Jun 22 11:39:21 volumio sshd[6135]: Received disconnect from 192.168.0.88 port 38980:11: disconnected by user Jun 22 11:39:21 volumio sshd[6135]: Disconnected from user volumio 192.168.0.88 port 38980 Jun 22 11:39:21 volumio sshd[6111]: pam_unix(sshd:session): session closed for user volumio Jun 22 11:39:21 volumio systemd[1]: session-3.scope: Succeeded. Jun 22 11:39:21 volumio systemd-logind[546]: Session 3 logged out. Waiting for processes to exit. Jun 22 11:39:21 volumio systemd-logind[546]: Removed session 3. Jun 22 11:39:32 volumio systemd[1]: Stopping User Manager for UID 1000... Jun 22 11:39:32 volumio systemd[6116]: Stopped target Default. Jun 22 11:39:32 volumio systemd[6116]: Stopped target Basic System. Jun 22 11:39:32 volumio systemd[6116]: Stopped target Timers. Jun 22 11:39:32 volumio systemd[6116]: Stopped target Sockets. Jun 22 11:39:32 volumio systemd[6116]: dbus.socket: Succeeded. Jun 22 11:39:32 volumio systemd[6116]: Closed D-Bus User Message Bus Socket. Jun 22 11:39:32 volumio systemd[6116]: gpg-agent-browser.socket: Succeeded. Jun 22 11:39:32 volumio systemd[6116]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers). Jun 22 11:39:32 volumio systemd[6116]: gpg-agent-ssh.socket: Succeeded. Jun 22 11:39:32 volumio systemd[6116]: Closed GnuPG cryptographic agent (ssh-agent emulation). Jun 22 11:39:32 volumio systemd[6116]: dirmngr.socket: Succeeded. Jun 22 11:39:32 volumio systemd[6116]: Closed GnuPG network certificate management daemon. Jun 22 11:39:32 volumio systemd[6116]: gpg-agent-extra.socket: Succeeded. Jun 22 11:39:32 volumio systemd[6116]: Closed GnuPG cryptographic agent and passphrase cache (restricted). Jun 22 11:39:32 volumio systemd[6116]: gpg-agent.socket: Succeeded. Jun 22 11:39:32 volumio systemd[6116]: Closed GnuPG cryptographic agent and passphrase cache. Jun 22 11:39:32 volumio systemd[6116]: Stopped target Paths. Jun 22 11:39:32 volumio systemd[6116]: pulseaudio.socket: Succeeded. Jun 22 11:39:32 volumio systemd[6116]: Closed Sound System. Jun 22 11:39:32 volumio systemd[6116]: Reached target Shutdown. Jun 22 11:39:32 volumio systemd[6116]: systemd-exit.service: Succeeded. Jun 22 11:39:32 volumio systemd[6116]: Started Exit the Session. Jun 22 11:39:32 volumio systemd[6116]: Reached target Exit the Session. Jun 22 11:39:32 volumio systemd[6117]: pam_unix(systemd-user:session): session closed for user volumio Jun 22 11:39:32 volumio systemd[1]: user@1000.service: Succeeded. Jun 22 11:39:32 volumio systemd[1]: Stopped User Manager for UID 1000. Jun 22 11:39:32 volumio systemd[1]: Stopping User Runtime Directory /run/user/1000... Jun 22 11:39:32 volumio systemd[1]: run-user-1000.mount: Succeeded. Jun 22 11:39:32 volumio systemd[1]: user-runtime-dir@1000.service: Succeeded. Jun 22 11:39:32 volumio systemd[1]: Stopped User Runtime Directory /run/user/1000. Jun 22 11:39:32 volumio systemd[1]: Removed slice User Slice of UID 1000. Jun 22 11:39:52 volumio volumio[975]: verbose: New Socket.io Connection to 192.168.0.46 from 192.168.0.88 UA: Mozilla/5.0 (X11; Linux x86_64; rv:139.0) Gecko/20100101 Firefox/139.0 Engine version: 3 Transport: polling Total Clients: 4 Jun 22 11:39:52 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::volumioGetVisibleSources Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:39:53 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 22 11:39:53 volumio volumio[975]: info: Received Get System Info Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 22 11:39:53 volumio volumio[975]: info: Discovery: Getting this device information Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:39:53 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:39:53 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:53 volumio volumio[975]: info: Listing playlists Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 22 11:39:53 volumio volumio[975]: info: VolumeController::SetAlsaVolume91 Jun 22 11:39:53 volumio volumio[975]: info: CoreStateMachine::pushState Jun 22 11:39:53 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::volumioPushState Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 22 11:39:53 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:39:53 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:54 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 22 11:39:54 volumio volumio[975]: info: Received Get System Info Jun 22 11:39:54 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 22 11:39:54 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 22 11:39:54 volumio volumio[975]: info: Discovery: Getting this device information Jun 22 11:39:54 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:39:54 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:54 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 22 11:39:54 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 22 11:39:54 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 22 11:39:56 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 22 11:39:56 volumio volumio[975]: info: Received Get System Info Jun 22 11:39:56 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 22 11:39:56 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 22 11:39:56 volumio volumio[975]: info: Discovery: Getting this device information Jun 22 11:39:56 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:39:56 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:56 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 22 11:39:58 volumio volumio[975]: info: Received Get System Info Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 22 11:39:58 volumio volumio[975]: info: Discovery: Getting this device information Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:39:58 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 22 11:39:58 volumio volumio[975]: info: Received Get System Info Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 22 11:39:58 volumio volumio[975]: info: Discovery: Getting this device information Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:39:58 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:39:58 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 22 11:40:02 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 22 11:40:02 volumio volumio[975]: info: Enabling plugin spop Jun 22 11:40:02 volumio volumio[975]: info: Loading plugin "spop"... Jun 22 11:40:04 volumio volumio[975]: info: PLUGIN START: spop Jun 22 11:40:04 volumio volumio[975]: info: Creating Spotify config file Jun 22 11:40:04 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 22 11:40:04 volumio volumio[975]: info: Done. Jun 22 11:40:04 volumio volumio[975]: info: Spotify config file written Jun 22 11:40:04 volumio volumio[975]: info: No need to fix Spotify hosts Jun 22 11:40:04 volumio sudo[6282]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 22 11:40:04 volumio sudo[6282]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 22 11:40:05 volumio systemd[1]: Started go-librespot Daemon. Jun 22 11:40:05 volumio sudo[6282]: pam_unix(sudo:session): session closed for user root Jun 22 11:40:05 volumio go-librespot[6284]: go-librespot daemon starting... Jun 22 11:40:05 volumio go-librespot[6284]: time="2025-06-22T11:40:05+08:00" level=info msg="running go-librespot 0.2.0" Jun 22 11:40:05 volumio go-librespot[6284]: time="2025-06-22T11:40:05+08:00" level=debug msg="app state loaded" Jun 22 11:40:05 volumio go-librespot[6284]: time="2025-06-22T11:40:05+08:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 22 11:40:05 volumio volumio[975]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 22 11:40:05 volumio volumio[975]: SPOTIFY: BQBIUAK5pUMOUk2gPGCnZajIkCsgBSutWeDu0XqneTlhC-9rIxUmPNzzAE8l44k8PtGJTtWQpYkrfRc8CghhdAGPLuZrymPp3waj-WnreqBqxSkVjKE1sP57oiDEZHbUhlo_bU9_j8NMCDq17rTN1s4_IRQTIucdCLENESsrJzm-8bEStus8Z6uHL6WQ2oEJ4ah-PjZiHz6noZ3AZIq-VJHCStC725a6umL6yG2Gz5-_FL7JC5UZiqSco0vx1J_q__tny-2DF2pKopEwNbuZBOP4qvAm5Rn86P5GDG-drxcuMJU Jun 22 11:40:05 volumio volumio[975]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 22 11:40:05 volumio volumio[975]: info: New Spotify access token = BQBIUAK5pUMOUk2gPGCnZajIkCsgBSutWeDu0XqneTlhC-9rIxUmPNzzAE8l44k8PtGJTtWQpYkrfRc8CghhdAGPLuZrymPp3waj-WnreqBqxSkVjKE1sP57oiDEZHbUhlo_bU9_j8NMCDq17rTN1s4_IRQTIucdCLENESsrJzm-8bEStus8Z6uHL6WQ2oEJ4ah-PjZiHz6noZ3AZIq-VJHCStC725a6umL6yG2Gz5-_FL7JC5UZiqSco0vx1J_q__tny-2DF2pKopEwNbuZBOP4qvAm5Rn86P5GDG-drxcuMJU Jun 22 11:40:05 volumio volumio[975]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 22 11:40:05 volumio go-librespot[6284]: time="2025-06-22T11:40:05+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]" Jun 22 11:40:05 volumio go-librespot[6284]: time="2025-06-22T11:40:05+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]" Jun 22 11:40:05 volumio go-librespot[6284]: time="2025-06-22T11:40:05+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]" Jun 22 11:40:05 volumio go-librespot[6284]: time="2025-06-22T11:40:05+08:00" level=info msg="zeroconf server listening on port 44077" Jun 22 11:40:05 volumio volumio[975]: SPOTIFY: User informations: {"country":"TW","display_name":"cftyn","email":"cftyn1+spotify@gmail.com","explicit_content":{"filter_enabled":true,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/8dlrqvnnthe96619360960o0g"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/8dlrqvnnthe96619360960o0g","id":"8dlrqvnnthe96619360960o0g","images":[],"product":"premium","type":"user","uri":"spotify:user:8dlrqvnnthe96619360960o0g"} Jun 22 11:40:05 volumio volumio[975]: info: Spotify Successfully logged in Jun 22 11:40:05 volumio volumio[975]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 22 11:40:05 volumio volumio[975]: info: [1750563605906] CoreMusicLibrary::Adding element Spotify Jun 22 11:40:05 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 22 11:40:05 volumio volumio[975]: Cannot find translation for source YouTube2 Jun 22 11:40:05 volumio volumio[975]: Cannot find translation for source Spotify Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="obtained new client token: AABPJMFyryk5sHltyghZwbKT8LoR3dAw2ONIn+ncQ0ORTHVNELbVqeoa4XrQgVh4Z9K7cgJPkYPE7TKO6AXDG+SbF/ac8p7+mbYFiSxU+EHv/ra56QHDiclc8HpCWRUSh4VF0xy4/NOJMAHjwUlGNQ5MKn3NKW0uPUQ8WrBFXEmQwXH2iYFO6zL2L7TtXDYXGrle+m5OPOO0ed9zrjDtKJuGgu9NESQnboyBSi3Lb7LR/I6/yoB7356Y" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="completed keyexchange" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="completed challenge" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=info msg="authenticated AP as 8dlrqvnnthe96619360960o0g" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=info msg="authenticated Login5 as 8dlrqvnnthe96619360960o0g" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="initializing zeroconf session, username: 8dlrqvnnthe96619360960o0g" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="dealer connection opened" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=trace msg="starting accesspoint recv loop" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=trace msg="starting dealer recv loop" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=trace msg="received accesspoint ping" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="received connection id: MjU5NTE4MTgtMWU5NC00MmVkLTkwYjItMzI1MjRjNzJhMGFjK2RlYWxlcit0Y3A6Ly8wYWM5NDkwOC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMkI5MzI5NzdGQUJEOUVCNTI4QUQyQjE2NzRGQkI3NEYzQTkzMDJBQjM3NEZGQ0M0QkFCODM2MUZDNkZGRDlDMw==" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=trace msg="received accesspoint pong ack" Jun 22 11:40:06 volumio go-librespot[6284]: time="2025-06-22T11:40:06+08:00" level=debug msg="put connect state because NEW_DEVICE" Jun 22 11:40:08 volumio volumio[975]: info: go-librespot daemon successfully initialized Jun 22 11:40:11 volumio volumio[975]: info: Initializing connection to go-librespot Websocket Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="new websocket client" Jun 22 11:40:11 volumio volumio[975]: info: Connection to go-librespot Websocket established Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="handling transfer player command from 20ef4c3bb8a38b8a71819ffe4ea651b65ce4102f" Jun 22 11:40:11 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 22 11:40:11 volumio volumio[975]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 22 11:40:11 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 22 11:40:11 volumio volumio[975]: info: Received Get System Version Jun 22 11:40:11 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 22 11:40:11 volumio volumio[975]: info: Received Get System Info Jun 22 11:40:11 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 22 11:40:11 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 22 11:40:11 volumio volumio[975]: info: Discovery: Getting this device information Jun 22 11:40:11 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:40:11 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:40:11 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EIXCmXCefcBWn" Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EIXCmXCefcBWn" Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="loading track (paused: true, position: 9312ms)" uri="spotify:track:5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=trace msg="emitting websocket event: will_play" Jun 22 11:40:11 volumio volumio[975]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5NITYjCmkHJEm03GUor1R1","play_origin":"playlist"}} Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="selected format OGG_VORBIS_320 (0062035a14c465378afb86214cff7f95aa84f68f)" uri="spotify:track:5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="requested aes key for file 0062035a14c465378afb86214cff7f95aa84f68f, gid: 5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:11 volumio go-librespot[6284]: time="2025-06-22T11:40:11+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1364" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1128" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="fetched first chunk of 12, total size is 6273472 bytes" uri="spotify:track:5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=trace msg="seek to 9312ms (diff: 130ms, samples: 410659, bytes: 286413)" uri="spotify:track:5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="created new output device" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=info msg="loaded track \"回る空うさぎ\" (paused: true, position: 9312ms, duration: 172753ms, prefetched: false)" uri="spotify:track:5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=trace msg="emitting websocket event: metadata" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=trace msg="emitting websocket event: active" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="sending successful reply for dealer request" Jun 22 11:40:12 volumio volumio[975]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5NITYjCmkHJEm03GUor1R1","name":"回る空うさぎ","artist_names":["DAZBEE"],"album_name":"Remindful.One","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f768912e6775efdcf712dcce","position":9312,"duration":172753,"release_date":"year:2022 month:1 day:25","track_number":1,"disc_number":1}} Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 22 11:40:12 volumio volumio[975]: SPOTIFY: received: {"type":"active","data":null} Jun 22 11:40:12 volumio volumio[975]: info: Aligning Spotify Volume to Volumio Volume Jun 22 11:40:12 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Jun 22 11:40:12 volumio volumio[975]: info: CorePlayQueue::getTrack 0 Jun 22 11:40:12 volumio volumio[975]: info: Setting Spotify Volume from Volumio: 91 Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=trace msg="emitting websocket event: paused" Jun 22 11:40:12 volumio volumio[975]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:5NITYjCmkHJEm03GUor1R1","play_origin":"playlist"}} Jun 22 11:40:12 volumio volumio[975]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 22 11:40:12 volumio volumio[975]: TypeError: Cannot read property 'service' of undefined Jun 22 11:40:12 volumio volumio[975]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) Jun 22 11:40:12 volumio volumio[975]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:274:18) Jun 22 11:40:12 volumio volumio[975]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) Jun 22 11:40:12 volumio volumio[975]: at WebSocket.emit (events.js:315:20) Jun 22 11:40:12 volumio volumio[975]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jun 22 11:40:12 volumio volumio[975]: at Receiver.emit (events.js:315:20) Jun 22 11:40:12 volumio volumio[975]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jun 22 11:40:12 volumio volumio[975]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 22 11:40:12 volumio volumio[975]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 22 11:40:12 volumio volumio[975]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 22 11:40:12 volumio volumio[975]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:12 volumio go-librespot[6284]: time="2025-06-22T11:40:12+08:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:5NITYjCmkHJEm03GUor1R1" Jun 22 11:40:13 volumio sudo[6316]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-22 11:39 Jun 22 11:40:13 volumio sudo[6316]: 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="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 04:52:53 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="a72866a0de4045751d03a035de6290e1"