-- Logs begin at Tue 2025-06-10 15:41:22 CEST, end at Tue 2025-06-10 15:47:57 CEST. -- Jun 10 15:46:08 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:46:08 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:46:08 volumio volumio[976]: info: Listing playlists Jun 10 15:46:12 volumio go-librespot[1651]: time="2025-06-10T15:46:12+02:00" level=trace msg="sent dealer ping" Jun 10 15:46:12 volumio go-librespot[1651]: time="2025-06-10T15:46:12+02:00" level=trace msg="received dealer pong" Jun 10 15:46:18 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:46:18 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:46:28 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:46:28 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:46:28 volumio volumio[976]: info: Listing playlists Jun 10 15:46:28 volumio volumio[976]: info: Listing playlists Jun 10 15:46:30 volumio volumio[976]: info: Creating user directories (if not exist) Jun 10 15:46:30 volumio sudo[2037]: pam_unix(sudo:session): session closed for user root Jun 10 15:46:30 volumio volumio[976]: info: Now Playing plugin installed Jun 10 15:46:30 volumio volumio[976]: Plugin install end detected on script Jun 10 15:46:30 volumio volumio[976]: info: Install script completed Jun 10 15:46:30 volumio volumio[976]: info: Adding reference to registry Jun 10 15:46:30 volumio volumio[976]: info: Done installing plugin. Jun 10 15:46:30 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 10 15:46:30 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 10 15:46:30 volumio volumio[976]: info: Folder /tmp/plugins removed Jun 10 15:46:30 volumio volumio[976]: info: Folder /tmp/downloaded_plugin.zip removed Jun 10 15:46:30 volumio volumio[976]: info: Folder /data/temp removed Jun 10 15:46:38 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:46:38 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:46:42 volumio go-librespot[1651]: time="2025-06-10T15:46:42+02:00" level=trace msg="sent dealer ping" Jun 10 15:46:42 volumio go-librespot[1651]: time="2025-06-10T15:46:42+02:00" level=trace msg="received dealer pong" Jun 10 15:46:48 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:46:48 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:46:48 volumio volumio[976]: info: Listing playlists Jun 10 15:46:48 volumio volumio[976]: info: Listing playlists Jun 10 15:46:49 volumio sshd[2148]: Accepted password for volumio from 192.168.0.31 port 43186 ssh2 Jun 10 15:46:49 volumio sshd[2148]: pam_unix(sshd:session): session opened for user volumio by (uid=0) Jun 10 15:46:50 volumio systemd[1]: Created slice User Slice of UID 1000. Jun 10 15:46:50 volumio systemd[1]: Starting User Runtime Directory /run/user/1000... Jun 10 15:46:50 volumio systemd-logind[606]: New session 1 of user volumio. Jun 10 15:46:50 volumio systemd[1]: Started User Runtime Directory /run/user/1000. Jun 10 15:46:50 volumio systemd[1]: Starting User Manager for UID 1000... Jun 10 15:46:50 volumio systemd[2194]: pam_unix(systemd-user:session): session opened for user volumio by (uid=0) Jun 10 15:46:50 volumio systemd[2194]: Listening on GnuPG cryptographic agent (ssh-agent emulation). Jun 10 15:46:50 volumio systemd[2194]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers). Jun 10 15:46:50 volumio systemd[2194]: Listening on Sound System. Jun 10 15:46:50 volumio systemd[2194]: Starting D-Bus User Message Bus Socket. Jun 10 15:46:50 volumio systemd[2194]: Reached target Timers. Jun 10 15:46:50 volumio systemd[2194]: Listening on GnuPG network certificate management daemon. Jun 10 15:46:50 volumio systemd[2194]: Listening on GnuPG cryptographic agent and passphrase cache (restricted). Jun 10 15:46:50 volumio systemd[2194]: Listening on GnuPG cryptographic agent and passphrase cache. Jun 10 15:46:50 volumio systemd[2194]: Reached target Paths. Jun 10 15:46:50 volumio systemd[2194]: Listening on D-Bus User Message Bus Socket. Jun 10 15:46:50 volumio systemd[2194]: Reached target Sockets. Jun 10 15:46:50 volumio systemd[2194]: Reached target Basic System. Jun 10 15:46:50 volumio systemd[2194]: Reached target Default. Jun 10 15:46:50 volumio systemd[2194]: Startup finished in 337ms. Jun 10 15:46:50 volumio systemd[1]: Started User Manager for UID 1000. Jun 10 15:46:50 volumio systemd[1]: Started Session 1 of user volumio. Jun 10 15:46:58 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:46:58 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:08 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:47:08 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:08 volumio volumio[976]: info: Listing playlists Jun 10 15:47:08 volumio volumio[976]: info: Listing playlists Jun 10 15:47:09 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:09 volumio volumio[976]: info: CorePlayQueue::getTrack 23 Jun 10 15:47:09 volumio volumio[976]: info: Prefetching next song Jun 10 15:47:09 volumio volumio[976]: info: [1749563229296] ControllerSpotify::prefetch Jun 10 15:47:09 volumio volumio[976]: info: Sending Spotify command with payload to local API: /player/add_to_queue Jun 10 15:47:09 volumio go-librespot[1651]: time="2025-06-10T15:47:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 10 15:47:09 volumio go-librespot[1651]: time="2025-06-10T15:47:09+02:00" level=debug msg="prefetching next track" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:09 volumio go-librespot[1651]: time="2025-06-10T15:47:09+02:00" level=debug msg="selected format OGG_VORBIS_160 (6e0f6f786560a7c15cac76a4d6891a4f033b6b4e)" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:09 volumio go-librespot[1651]: time="2025-06-10T15:47:09+02:00" level=debug msg="requested aes key for file 6e0f6f786560a7c15cac76a4d6891a4f033b6b4e, gid: 7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:09 volumio go-librespot[1651]: time="2025-06-10T15:47:09+02:00" level=debug msg="fetched first chunk of 5, total size is 2404023 bytes" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:09 volumio go-librespot[1651]: time="2025-06-10T15:47:09+02:00" level=info msg="prefetched track \"Running Around\" (duration: 124620ms)" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:10 volumio go-librespot[1651]: time="2025-06-10T15:47:10+02:00" level=debug msg="fetched chunk 1/4, size: 524288" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:10 volumio go-librespot[1651]: time="2025-06-10T15:47:10+02:00" level=debug msg="fetched chunk 2/4, size: 524288" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:10 volumio go-librespot[1651]: time="2025-06-10T15:47:10+02:00" level=debug msg="fetched chunk 3/4, size: 524288" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=trace msg="sent dealer ping" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=trace msg="received dealer pong" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=trace msg="emitting websocket event: not_playing" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:2A1aS3mwuGuX2yk1bgxOvA","play_origin":"go-librespot"}} Jun 10 15:47:12 volumio volumio[976]: error: Failed to decode event: not_playing Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:2A1aS3mwuGuX2yk1bgxOvA","play_origin":"go-librespot"}} Jun 10 15:47:12 volumio volumio[976]: error: Failed to decode event: not_playing Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=trace msg="emitting websocket event: will_play" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=info msg="loaded track \"Running Around\" (paused: false, position: 0ms, duration: 124620ms, prefetched: true)" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","play_origin":"go-librespot"}} Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","play_origin":"go-librespot"}} Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=trace msg="scheduling prefetch in 95s" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=trace msg="emitting websocket event: metadata" Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","name":"Running Around","artist_names":["Ely Oaks"],"album_name":"Running Around","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","position":0,"duration":124620,"release_date":"year:2025 month:1 day:31","track_number":1,"disc_number":1}} Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","name":"Running Around","artist_names":["Ely Oaks"],"album_name":"Running Around","album_cover_url":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","position":0,"duration":124620,"release_date":"year:2025 month:1 day:31","track_number":1,"disc_number":1}} Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 10 15:47:12 volumio go-librespot[1651]: time="2025-06-10T15:47:12+02:00" level=trace msg="emitting websocket event: playing" Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","play_origin":"go-librespot"}} Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: PUSH STATE SPOTIFY Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: {"status":"play","service":"spop","title":"Running Around","artist":"Ely Oaks","album":"Running Around","albumart":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 10 15:47:12 volumio volumio[976]: info: CoreCommandRouter::servicePushState Jun 10 15:47:12 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:12 volumio volumio[976]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Running Around","artist":"Ely Oaks","album":"Running Around","albumart":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 10 15:47:12 volumio volumio[976]: verbose: CURRENT POSITION 22 Jun 10 15:47:12 volumio volumio[976]: info: CoreStateMachine::syncState stateService play Jun 10 15:47:12 volumio volumio[976]: info: CoreStateMachine::syncState currentStatus play Jun 10 15:47:12 volumio volumio[976]: info: Received an update from plugin. extracting info from payload Jun 10 15:47:12 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:12 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:12 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 15:47:12 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:12 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:12 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:12 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","play_origin":"go-librespot"}} Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: PUSH STATE SPOTIFY Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: {"status":"play","service":"spop","title":"Running Around","artist":"Ely Oaks","album":"Running Around","albumart":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 10 15:47:12 volumio volumio[976]: info: CoreCommandRouter::servicePushState Jun 10 15:47:12 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:12 volumio volumio[976]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Running Around","artist":"Ely Oaks","album":"Running Around","albumart":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 10 15:47:12 volumio volumio[976]: verbose: CURRENT POSITION 22 Jun 10 15:47:12 volumio volumio[976]: info: CoreStateMachine::syncState stateService play Jun 10 15:47:12 volumio volumio[976]: info: CoreStateMachine::syncState currentStatus play Jun 10 15:47:12 volumio volumio[976]: info: Received an update from plugin. extracting info from payload Jun 10 15:47:12 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:12 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:12 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:12 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:12 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:12 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:12 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:13 volumio volumio[976]: SPOTIFY: PUSH STATE SPOTIFY Jun 10 15:47:13 volumio volumio[976]: SPOTIFY: {"status":"play","service":"spop","title":"Running Around","artist":"Ely Oaks","album":"Running Around","albumart":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 10 15:47:13 volumio volumio[976]: info: CoreCommandRouter::servicePushState Jun 10 15:47:13 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:13 volumio volumio[976]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Running Around","artist":"Ely Oaks","album":"Running Around","albumart":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 10 15:47:13 volumio volumio[976]: verbose: CURRENT POSITION 22 Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::syncState stateService play Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::syncState currentStatus play Jun 10 15:47:13 volumio volumio[976]: info: Received an update from plugin. extracting info from payload Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:13 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:13 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 15:47:13 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:13 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:13 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:13 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:13 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:13 volumio volumio[976]: SPOTIFY: PUSH STATE SPOTIFY Jun 10 15:47:13 volumio volumio[976]: SPOTIFY: {"status":"play","service":"spop","title":"Running Around","artist":"Ely Oaks","album":"Running Around","albumart":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 10 15:47:13 volumio volumio[976]: info: CoreCommandRouter::servicePushState Jun 10 15:47:13 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:13 volumio volumio[976]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Running Around","artist":"Ely Oaks","album":"Running Around","albumart":"https://i.scdn.co/image/ab67616d00001e026e2c3a9218378061c1a1b2b0","uri":"spotify:track:7yNQ5oPcuCC4wTqTcMRIrE","trackType":"spotify","seek":0,"duration":124,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jun 10 15:47:13 volumio volumio[976]: verbose: CURRENT POSITION 22 Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::syncState stateService play Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::syncState currentStatus play Jun 10 15:47:13 volumio volumio[976]: info: Received an update from plugin. extracting info from payload Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:13 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:13 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 15:47:13 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:13 volumio volumio[976]: info: CorePlayQueue::getTrack 22 Jun 10 15:47:13 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:13 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:13 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:13 volumio volumio[976]: info: CoreStateMachine::startPlaybackTimer Jun 10 15:47:13 volumio volumio[976]: info: CorePlayQueue::getTrack 23 Jun 10 15:47:14 volumio volumio[976]: info: CoreStateMachine::pushState Jun 10 15:47:14 volumio volumio[976]: info: CorePlayQueue::getTrack 23 Jun 10 15:47:14 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 15:47:14 volumio volumio[976]: info: CoreCommandRouter::volumioPushState Jun 10 15:47:14 volumio volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jun 10 15:47:18 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:47:18 volumio volumio[976]: info: CorePlayQueue::getTrack 23 Jun 10 15:47:21 volumio sshd[2213]: Received disconnect from 192.168.0.31 port 43186:11: disconnected by user Jun 10 15:47:21 volumio sshd[2213]: Disconnected from user volumio 192.168.0.31 port 43186 Jun 10 15:47:21 volumio sshd[2148]: pam_unix(sshd:session): session closed for user volumio Jun 10 15:47:21 volumio systemd[1]: session-1.scope: Succeeded. Jun 10 15:47:21 volumio systemd-logind[606]: Session 1 logged out. Waiting for processes to exit. Jun 10 15:47:21 volumio systemd-logind[606]: Removed session 1. Jun 10 15:47:26 volumio volumio[976]: info: Enabling plugin now_playing Jun 10 15:47:26 volumio volumio[976]: info: Loading plugin "now_playing"... Jun 10 15:47:26 volumio volumio[976]: error: !!!! WARNING !!!! Jun 10 15:47:26 volumio volumio[976]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Jun 10 15:47:26 volumio volumio[976]: Require stack: Jun 10 15:47:26 volumio volumio[976]: - /data/plugins/user_interface/now_playing/dist/index.js Jun 10 15:47:26 volumio volumio[976]: - /volumio/app/pluginmanager.js Jun 10 15:47:26 volumio volumio[976]: - /volumio/app/index.js Jun 10 15:47:26 volumio volumio[976]: - /volumio/index.js Jun 10 15:47:26 volumio volumio[976]: error: Stack trace: Error: Cannot find module 'geo-tz' Jun 10 15:47:26 volumio volumio[976]: Require stack: Jun 10 15:47:26 volumio volumio[976]: - /data/plugins/user_interface/now_playing/dist/index.js Jun 10 15:47:26 volumio volumio[976]: - /volumio/app/pluginmanager.js Jun 10 15:47:26 volumio volumio[976]: - /volumio/app/index.js Jun 10 15:47:26 volumio volumio[976]: - /volumio/index.js Jun 10 15:47:26 volumio volumio[976]: at Function.Module._resolveFilename (internal/modules/cjs/loader.js:880:15) Jun 10 15:47:26 volumio volumio[976]: at Function.Module._load (internal/modules/cjs/loader.js:725:27) Jun 10 15:47:26 volumio volumio[976]: at Module.require (internal/modules/cjs/loader.js:952:19) Jun 10 15:47:26 volumio volumio[976]: at require (internal/modules/cjs/helpers.js:88:18) Jun 10 15:47:26 volumio volumio[976]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:46:34) Jun 10 15:47:26 volumio volumio[976]: at Module._compile (internal/modules/cjs/loader.js:1063:30) Jun 10 15:47:26 volumio volumio[976]: at Object.Module._extensions..js (internal/modules/cjs/loader.js:1092:10) Jun 10 15:47:26 volumio volumio[976]: at Module.load (internal/modules/cjs/loader.js:928:32) Jun 10 15:47:26 volumio volumio[976]: at Function.Module._load (internal/modules/cjs/loader.js:769:14) Jun 10 15:47:26 volumio volumio[976]: at Module.require (internal/modules/cjs/loader.js:952:19) Jun 10 15:47:26 volumio volumio[976]: at require (internal/modules/cjs/helpers.js:88:18) Jun 10 15:47:26 volumio volumio[976]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Jun 10 15:47:26 volumio volumio[976]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jun 10 15:47:26 volumio volumio[976]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jun 10 15:47:26 volumio volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Jun 10 15:47:26 volumio volumio[976]: error: !!!! WARNING !!!! Jun 10 15:47:26 volumio volumio[976]: info: Done. Jun 10 15:47:27 volumio volumio[976]: info: Enabling plugin now_playing Jun 10 15:47:27 volumio volumio[976]: info: Loading plugin "now_playing"... Jun 10 15:47:27 volumio volumio[976]: error: !!!! WARNING !!!! Jun 10 15:47:27 volumio volumio[976]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Jun 10 15:47:27 volumio volumio[976]: Require stack: Jun 10 15:47:27 volumio volumio[976]: - /data/plugins/user_interface/now_playing/dist/index.js Jun 10 15:47:27 volumio volumio[976]: - /volumio/app/pluginmanager.js Jun 10 15:47:27 volumio volumio[976]: - /volumio/app/index.js Jun 10 15:47:27 volumio volumio[976]: - /volumio/index.js Jun 10 15:47:27 volumio volumio[976]: error: Stack trace: Error: Cannot find module 'geo-tz' Jun 10 15:47:27 volumio volumio[976]: Require stack: Jun 10 15:47:27 volumio volumio[976]: - /data/plugins/user_interface/now_playing/dist/index.js Jun 10 15:47:27 volumio volumio[976]: - /volumio/app/pluginmanager.js Jun 10 15:47:27 volumio volumio[976]: - /volumio/app/index.js Jun 10 15:47:27 volumio volumio[976]: - /volumio/index.js Jun 10 15:47:27 volumio volumio[976]: at Function.Module._resolveFilename (internal/modules/cjs/loader.js:880:15) Jun 10 15:47:27 volumio volumio[976]: at Function.Module._load (internal/modules/cjs/loader.js:725:27) Jun 10 15:47:27 volumio volumio[976]: at Module.require (internal/modules/cjs/loader.js:952:19) Jun 10 15:47:27 volumio volumio[976]: at require (internal/modules/cjs/helpers.js:88:18) Jun 10 15:47:27 volumio volumio[976]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:46:34) Jun 10 15:47:27 volumio volumio[976]: at Module._compile (internal/modules/cjs/loader.js:1063:30) Jun 10 15:47:27 volumio volumio[976]: at Object.Module._extensions..js (internal/modules/cjs/loader.js:1092:10) Jun 10 15:47:27 volumio volumio[976]: at Module.load (internal/modules/cjs/loader.js:928:32) Jun 10 15:47:27 volumio volumio[976]: at Function.Module._load (internal/modules/cjs/loader.js:769:14) Jun 10 15:47:27 volumio volumio[976]: at Module.require (internal/modules/cjs/loader.js:952:19) Jun 10 15:47:27 volumio volumio[976]: at require (internal/modules/cjs/helpers.js:88:18) Jun 10 15:47:27 volumio volumio[976]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Jun 10 15:47:27 volumio volumio[976]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jun 10 15:47:27 volumio volumio[976]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jun 10 15:47:27 volumio volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Jun 10 15:47:27 volumio volumio[976]: error: !!!! WARNING !!!! Jun 10 15:47:27 volumio volumio[976]: info: Error: TypeError: Cannot read property 'printToastMessage' of null Jun 10 15:47:28 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:47:28 volumio volumio[976]: info: CorePlayQueue::getTrack 23 Jun 10 15:47:28 volumio volumio[976]: info: Listing playlists Jun 10 15:47:28 volumio volumio[976]: info: Listing playlists Jun 10 15:47:32 volumio systemd[1]: Stopping User Manager for UID 1000... Jun 10 15:47:32 volumio systemd[2194]: Stopped target Default. Jun 10 15:47:32 volumio systemd[2194]: Stopped target Basic System. Jun 10 15:47:32 volumio systemd[2194]: Stopped target Timers. Jun 10 15:47:32 volumio systemd[2194]: Stopped target Paths. Jun 10 15:47:32 volumio systemd[2194]: Stopped target Sockets. Jun 10 15:47:32 volumio systemd[2194]: dbus.socket: Succeeded. Jun 10 15:47:32 volumio systemd[2194]: Closed D-Bus User Message Bus Socket. Jun 10 15:47:32 volumio systemd[2194]: pulseaudio.socket: Succeeded. Jun 10 15:47:32 volumio systemd[2194]: Closed Sound System. Jun 10 15:47:32 volumio systemd[2194]: gpg-agent-extra.socket: Succeeded. Jun 10 15:47:32 volumio systemd[2194]: Closed GnuPG cryptographic agent and passphrase cache (restricted). Jun 10 15:47:32 volumio systemd[2194]: gpg-agent-ssh.socket: Succeeded. Jun 10 15:47:32 volumio systemd[2194]: Closed GnuPG cryptographic agent (ssh-agent emulation). Jun 10 15:47:32 volumio systemd[2194]: gpg-agent.socket: Succeeded. Jun 10 15:47:32 volumio systemd[2194]: Closed GnuPG cryptographic agent and passphrase cache. Jun 10 15:47:32 volumio systemd[2194]: gpg-agent-browser.socket: Succeeded. Jun 10 15:47:32 volumio systemd[2194]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers). Jun 10 15:47:32 volumio systemd[2194]: dirmngr.socket: Succeeded. Jun 10 15:47:32 volumio systemd[2194]: Closed GnuPG network certificate management daemon. Jun 10 15:47:32 volumio systemd[2194]: Reached target Shutdown. Jun 10 15:47:32 volumio systemd[2194]: systemd-exit.service: Succeeded. Jun 10 15:47:32 volumio systemd[2194]: Started Exit the Session. Jun 10 15:47:32 volumio systemd[2194]: Reached target Exit the Session. Jun 10 15:47:32 volumio systemd[2195]: pam_unix(systemd-user:session): session closed for user volumio Jun 10 15:47:32 volumio systemd[1]: user@1000.service: Succeeded. Jun 10 15:47:32 volumio systemd[1]: Stopped User Manager for UID 1000. Jun 10 15:47:32 volumio systemd[1]: Stopping User Runtime Directory /run/user/1000... Jun 10 15:47:32 volumio systemd[1]: run-user-1000.mount: Succeeded. Jun 10 15:47:32 volumio systemd[1]: user-runtime-dir@1000.service: Succeeded. Jun 10 15:47:32 volumio systemd[1]: Stopped User Runtime Directory /run/user/1000. Jun 10 15:47:32 volumio systemd[1]: Removed slice User Slice of UID 1000. Jun 10 15:47:32 volumio volumio[976]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 10 15:47:32 volumio volumio[976]: info: AutoStart - getUIConfig Jun 10 15:47:36 volumio volumio[976]: info: CALLMETHOD: system_controller autostart saveOptions [object Object] Jun 10 15:47:36 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: autostart , saveOptions Jun 10 15:47:36 volumio volumio[976]: info: AutoStart - saving settings Jun 10 15:47:36 volumio volumio[976]: error: Failed callmethod call: TypeError: Cannot read property 'printToastMessage' of null Jun 10 15:47:38 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 10 15:47:38 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 10 15:47:38 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:47:38 volumio volumio[976]: info: CorePlayQueue::getTrack 23 Jun 10 15:47:38 volumio go-librespot[1651]: time="2025-06-10T15:47:38+02:00" level=debug msg="fetched chunk 4/4, size: 306871" uri="spotify:track:7yNQ5oPcuCC4wTqTcMRIrE" Jun 10 15:47:41 volumio go-librespot[1651]: time="2025-06-10T15:47:41+02:00" level=trace msg="received accesspoint ping" Jun 10 15:47:41 volumio go-librespot[1651]: time="2025-06-10T15:47:41+02:00" level=trace msg="received accesspoint pong ack" Jun 10 15:47:42 volumio go-librespot[1651]: time="2025-06-10T15:47:42+02:00" level=trace msg="sent dealer ping" Jun 10 15:47:42 volumio go-librespot[1651]: time="2025-06-10T15:47:42+02:00" level=trace msg="received dealer pong" Jun 10 15:47:44 volumio volumio[976]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 10 15:47:47 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 10 15:47:47 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jun 10 15:47:48 volumio volumio[976]: info: CoreCommandRouter::volumioGetState Jun 10 15:47:48 volumio volumio[976]: info: CorePlayQueue::getTrack 23 Jun 10 15:47:48 volumio volumio[976]: info: Listing playlists Jun 10 15:47:48 volumio volumio[976]: info: Listing playlists Jun 10 15:47:51 volumio volumio[976]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 10 15:47:53 volumio volumio[976]: info: CALLMETHOD: user_interface Systeminfo getsysteminfo undefined Jun 10 15:47:53 volumio volumio[976]: info: CoreCommandRouter::executeOnPlugin: Systeminfo , getsysteminfo Jun 10 15:47:53 volumio sudo[2348]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/vcgencmd version Jun 10 15:47:53 volumio sudo[2348]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 10 15:47:53 volumio sudo[2348]: pam_unix(sudo:session): session closed for user root Jun 10 15:47:55 volumio volumio[976]: info: board is Raspberry Pi 3 Model B Rev 1.2 Jun 10 15:47:55 volumio volumio[976]: Storage info 131M 128M 0M Jun 10 15:47:55 volumio volumio[976]: Storage info 131M 128M 0M Jun 10 15:47:55 volumio volumio[976]: Storage info 131M 128M 0M Jun 10 15:47:55 volumio volumio[976]: BBBBBBBBBBBBBB-CPU Temp 52 °C Jun 10 15:47:55 volumio volumio[976]: info: Firmware detected: Nov 11 2024 15:50:32 version 903570ba72a9e117f92e5499de439f59dd96e417 (clean) (release) (start) Jun 10 15:47:56 volumio volumio[976]: info: failed Error: Command failed: /data/plugins/user_interface/Systeminfo/hw_params hw:2 >/data/configuration/user_interface/Systeminfo/config.json Jun 10 15:47:56 volumio volumio[976]: cannot open device 'hw:2': Device or resource busy Jun 10 15:47:56 volumio volumio[976]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 10 15:47:56 volumio volumio[976]: TypeError: Cannot read property 'printToastMessage' of null Jun 10 15:47:56 volumio volumio[976]: at /volumio/app/index.js:1214:32 Jun 10 15:47:56 volumio volumio[976]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Jun 10 15:47:56 volumio volumio[976]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Jun 10 15:47:56 volumio volumio[976]: at CoreCommandRouter.pushToastMessage (/volumio/app/index.js:1212:13) Jun 10 15:47:56 volumio volumio[976]: at /data/plugins/user_interface/Systeminfo/index.js:156:38 Jun 10 15:47:56 volumio volumio[976]: at ChildProcess.exithandler (child_process.js:315:5) Jun 10 15:47:56 volumio volumio[976]: at ChildProcess.emit (events.js:315:20) Jun 10 15:47:56 volumio volumio[976]: at maybeClose (internal/child_process.js:1048:16) Jun 10 15:47:56 volumio volumio[976]: at Socket. (internal/child_process.js:439:11) Jun 10 15:47:56 volumio volumio[976]: at Socket.emit (events.js:315:20) Jun 10 15:47:56 volumio volumio[976]: at Pipe. (net.js:673:12) Jun 10 15:47:56 volumio volumio[976]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 10 15:47:57 volumio sudo[2853]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-10 15:46 Jun 10 15:47:57 volumio sudo[2853]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"