Dec 25 19:47:01 volumio go-librespot[1828]: time="2025-12-25T19:47:01+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 25 19:47:01 volumio go-librespot[1828]: time="2025-12-25T19:47:01+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 323" Dec 25 19:47:05 volumio go-librespot[1828]: time="2025-12-25T19:47:05+09:00" level=trace msg="sent dealer ping" Dec 25 19:47:05 volumio go-librespot[1828]: time="2025-12-25T19:47:05+09:00" level=trace msg="received dealer pong" Dec 25 19:47:15 volumio go-librespot[1828]: time="2025-12-25T19:47:15+09:00" level=debug msg="handling transfer player command from f7c5d01076b08390c764678e6e9b6e60348cd459" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=debug msg="resolved context of track" uri="spotify:album:2x6Q3LAtIb1j10PlkVjhP2" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:album:2x6Q3LAtIb1j10PlkVjhP2" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=debug msg="loading track (paused: true, position: 3571ms)" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=trace msg="emitting websocket event: will_play" Dec 25 19:47:20 volumio volumio[1376]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:2x6Q3LAtIb1j10PlkVjhP2","uri":"spotify:track:7hv0gfcH0giOfVSYGL3KgY","play_origin":"album"}} Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=debug msg="selected format OGG_VORBIS_320 (a322eea6d922535ad1b1e80cb1eac241ca6c592d)" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=debug msg="requested aes key for file a322eea6d922535ad1b1e80cb1eac241ca6c592d, gid: 7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1364" Dec 25 19:47:20 volumio go-librespot[1828]: time="2025-12-25T19:47:20+09:00" level=trace msg="found 3 cdn urls" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:21 volumio go-librespot[1828]: time="2025-12-25T19:47:21+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1126" Dec 25 19:47:25 volumio go-librespot[1828]: time="2025-12-25T19:47:25+09:00" level=trace msg="received accesspoint ping" Dec 25 19:47:25 volumio go-librespot[1828]: time="2025-12-25T19:47:25+09:00" level=trace msg="received accesspoint pong ack" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="fetched first chunk of 28, total size is 14557296 bytes" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=trace msg="seek to 3571ms (diff: 96ms, samples: 157481, bytes: 113201)" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="created new output device" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=info msg="loaded track \"Viva De Funk\" (paused: true, position: 3571ms, duration: 344106ms, prefetched: false)" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="fetched chunk 1/27, size: 524288" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=trace msg="emitting websocket event: metadata" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=trace msg="emitting websocket event: active" Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7hv0gfcH0giOfVSYGL3KgY","name":"Viva De Funk","artist_names":["Joe Sample"],"album_name":"The Best Of Joe Sample","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027ad55a213addda212b34e1cf","position":3571,"duration":344106,"release_date":"year:1998 month:7 day:17","track_number":1,"disc_number":1}} Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="sending successful reply for dealer request" Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: received: {"type":"active","data":null} Dec 25 19:47:26 volumio volumio[1376]: info: Aligning Spotify Volume to Volumio Volume Dec 25 19:47:26 volumio volumio[1376]: info: CoreCommandRouter::volumioGetState Dec 25 19:47:26 volumio volumio[1376]: info: CorePlayQueue::getTrack 0 Dec 25 19:47:26 volumio volumio[1376]: info: Setting Spotify Volume from Volumio: 27 Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="fetched chunk 2/27, size: 524288" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=trace msg="emitting websocket event: paused" Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:album:2x6Q3LAtIb1j10PlkVjhP2","uri":"spotify:track:7hv0gfcH0giOfVSYGL3KgY","play_origin":"album"}} Dec 25 19:47:26 volumio volumio[1376]: info: Spotify is playing in volatile mode Dec 25 19:47:26 volumio volumio[1376]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: UNSET VOLATILE Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: {"status":"play","position":0,"title":"Carmel","artist":"Joe Sample","album":"Carmel","albumart":"/albumart?cacheid=201&web=Joe%20Sample/Carmel/extralarge&path=%2FNAS%2FNAS%2F02.%20Jazz%2FJoe%20Sample%2FJoe%20Sample%20-%201979%20%20Carmel&metadata=false","uri":"mnt/NAS/NAS/02. Jazz/Joe Sample/Joe Sample - 1979 Carmel/01. Carmel.flac","trackType":"flac","seek":1375,"duration":339,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":27,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"flac","updatedb":false,"volatile":false,"service":"mpd"} Dec 25 19:47:26 volumio volumio[1376]: info: Setting Spotify stop after unset volatile call Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=info msg="playback was transferred to Web Player (Chrome)" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=trace msg="closed output device because of stop command" Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: PUSH STATE SPOTIFY Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: {"status":"pause","service":"spop","title":"Viva De Funk","artist":"Joe Sample","album":"The Best Of Joe Sample","albumart":"https://i.scdn.co/image/ab67616d00001e027ad55a213addda212b34e1cf","uri":"spotify:track:7hv0gfcH0giOfVSYGL3KgY","trackType":"spotify","seek":3571,"duration":344,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 25 19:47:26 volumio volumio[1376]: info: CoreCommandRouter::servicePushState Dec 25 19:47:26 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:47:26 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 19:47:26 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:47:26 volumio volumio[1376]: info: touch_display: Setting screensaver timeout to 120 seconds. Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="fetched chunk 3/27, size: 524288" uri="spotify:track:7hv0gfcH0giOfVSYGL3KgY" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="put connect state inactive" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=trace msg="emitting websocket event: inactive" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=trace msg="emitting websocket event: stopped" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="handling resume player command from f7c5d01076b08390c764678e6e9b6e60348cd459" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=warning msg="failed handling dealer request" error="no primary stream" Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: received: {"type":"inactive","data":null} Dec 25 19:47:26 volumio volumio[1376]: error: Failed to decode event: inactive Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: received: {"type":"stopped","data":{"play_origin":""}} Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: PUSH STATE SPOTIFY Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: {"status":"stop","service":"spop","title":"Viva De Funk","artist":"Joe Sample","album":"The Best Of Joe Sample","albumart":"https://i.scdn.co/image/ab67616d00001e027ad55a213addda212b34e1cf","uri":"spotify:track:7hv0gfcH0giOfVSYGL3KgY","trackType":"spotify","seek":3571,"duration":344,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 25 19:47:26 volumio volumio[1376]: info: CoreCommandRouter::servicePushState Dec 25 19:47:26 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:47:26 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 19:47:26 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:47:26 volumio volumio[1376]: info: CorePlayQueue::getTrack 0 Dec 25 19:47:26 volumio volumio[1376]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received spop Dec 25 19:47:26 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="dealer connection closed" Dec 25 19:47:26 volumio go-librespot[1828]: time="2025-12-25T19:47:26+09:00" level=debug msg="dealer recv loop stopped" Dec 25 19:47:27 volumio volumio[1376]: info: Spotify Stop Dec 25 19:47:27 volumio volumio[1376]: SPOTIFY: SPOTIFY STOP Dec 25 19:47:27 volumio volumio[1376]: SPOTIFY: {"status":"stop","title":"Viva De Funk","artist":"Joe Sample","album":"The Best Of Joe Sample","albumart":"https://i.scdn.co/image/ab67616d00001e027ad55a213addda212b34e1cf","uri":"spotify:track:7hv0gfcH0giOfVSYGL3KgY","trackType":"spotify","codec":"ogg","seek":3571,"duration":344,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":27,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Dec 25 19:47:28 volumio volumio[1376]: SPOTIFY: SETTING SPOTIFY VOLUME 27 Dec 25 19:47:28 volumio volumio[1376]: info: Sending Spotify command with payload to local API: /player/volume Dec 25 19:47:32 volumio go-librespot[1828]: time="2025-12-25T19:47:32+09:00" level=debug msg="obtained new client token: AAAU/pZAdRqgTCS1NrMDzApsONYQRGVb+ox2n4fBXRiaDKqPAvH81DN/9D1tamzk+ebdh1v30YrFOO7POZA9g58wVJFa0wWH1TSUuuKx2tj+DKBrOKBsGdyksY3LiyVVdfqUKYOkCFGZjnS3jLS1Q19Ja5zli7LBmXh2MvhmNJ1GoNrqRjHEW/lFz4x3XZTbkiGTNHsUpY9v+Jf07hVnJFBMslNVrvuYCQ9x4XRZ/344yISpKBdQDU5v1kA=" Dec 25 19:47:37 volumio go-librespot[1828]: time="2025-12-25T19:47:37+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 25 19:47:38 volumio sudo[1469]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 25 19:47:38 volumio sudo[1469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 19:47:38 volumio sudo[1469]: pam_unix(sudo:session): session closed for user root Dec 25 19:47:38 volumio sudo[1471]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 25 19:47:38 volumio sudo[1471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 25 19:47:38 volumio sudo[1471]: pam_unix(sudo:session): session closed for user root Dec 25 19:47:38 volumio volumio[1376]: verbose: New Socket.io Connection to 192.168.219.119 from 192.168.219.110 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/143.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::volumioGetVisibleSources Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::volumioGetState Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 25 19:47:38 volumio volumio[1376]: info: Received Get System Info Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 19:47:38 volumio volumio[1376]: info: Discovery: Getting this device information Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::volumioGetState Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::volumioGetState Dec 25 19:47:38 volumio volumio[1376]: info: Listing playlists Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 25 19:47:38 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Dec 25 19:47:39 volumio volumio[1376]: info: CoreCommandRouter::volumioGetState Dec 25 19:47:40 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Dec 25 19:47:40 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 25 19:47:40 volumio volumio[1376]: info: Received Get System Info Dec 25 19:47:40 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 19:47:40 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 19:47:40 volumio volumio[1376]: info: Discovery: Getting this device information Dec 25 19:47:40 volumio volumio[1376]: info: CoreCommandRouter::volumioGetState Dec 25 19:47:40 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 19:47:41 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 25 19:47:41 volumio volumio[1376]: info: Received Get System Info Dec 25 19:47:41 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 19:47:41 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 19:47:41 volumio volumio[1376]: info: Discovery: Getting this device information Dec 25 19:47:41 volumio volumio[1376]: info: CoreCommandRouter::volumioGetState Dec 25 19:47:41 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 19:47:41 volumio volumio[1376]: info: CoreCommandRouter::volumioVolatilePlay Dec 25 19:47:41 volumio volumio[1376]: info: CoreStateMachine::volatilePlay Dec 25 19:47:41 volumio volumio[1376]: info: WARNING: No play method for volatile plugin undefined Dec 25 19:47:42 volumio go-librespot[1828]: time="2025-12-25T19:47:42+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 25 19:47:42 volumio go-librespot[1828]: time="2025-12-25T19:47:42+09:00" level=debug msg="completed keyexchange" Dec 25 19:47:42 volumio go-librespot[1828]: time="2025-12-25T19:47:42+09:00" level=debug msg="completed challenge" Dec 25 19:47:42 volumio go-librespot[1828]: time="2025-12-25T19:47:42+09:00" level=info msg="authenticated AP" username="31************************mi" Dec 25 19:47:47 volumio go-librespot[1828]: time="2025-12-25T19:47:47+09:00" level=info msg="authenticated Login5" username="31************************mi" Dec 25 19:47:47 volumio volumio[1376]: info: CoreCommandRouter::volumioVolatilePlay Dec 25 19:47:47 volumio volumio[1376]: info: CoreStateMachine::volatilePlay Dec 25 19:47:47 volumio volumio[1376]: info: WARNING: No play method for volatile plugin undefined Dec 25 19:47:47 volumio go-librespot[1828]: time="2025-12-25T19:47:47+09: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]" Dec 25 19:47:47 volumio go-librespot[1828]: time="2025-12-25T19:47:47+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 25 19:47:47 volumio go-librespot[1828]: time="2025-12-25T19:47:47+09:00" level=debug msg="restored session after logout" username="31************************mi" Dec 25 19:47:48 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=debug msg="dealer connection opened" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=trace msg="starting accesspoint recv loop" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=trace msg="starting dealer recv loop" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=trace msg="received accesspoint ping" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=debug msg="received connection id: ZGEwMmQ5MTktYmNi...RjkxNDBGNUMwRA==" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=debug msg="put connect state because NEW_DEVICE" Dec 25 19:47:52 volumio go-librespot[1828]: time="2025-12-25T19:47:52+09:00" level=trace msg="received accesspoint pong ack" Dec 25 19:47:54 volumio volumio[1376]: info: CorePlayQueue::getTrack 0 Dec 25 19:47:54 volumio volumio[1376]: info: CorePlayQueue::getTrack 1 Dec 25 19:47:54 volumio volumio[1376]: info: Prefetching next song Dec 25 19:47:54 volumio volumio[1376]: info: DOING PREFETCH IN MPD Dec 25 19:47:54 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand add "NAS/NAS/02. Jazz/Joe Sample/Joe Sample - 1979 Carmel/02. Paintings.flac" Dec 25 19:47:54 volumio volumio[1376]: info: Dec 25 19:47:54 volumio volumio[1376]: ---------------------------- MPD announces system playlist update Dec 25 19:47:54 volumio volumio[1376]: info: Ignoring MPD Status Update Dec 25 19:47:54 volumio volumio[1376]: info: sendMpdCommand add "NAS/NAS/02. Jazz/Joe Sample/Joe Sample - 1979 Carmel/02. Paintings.flac" took 1 milliseconds Dec 25 19:47:54 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand consume 1 Dec 25 19:47:54 volumio volumio[1376]: info: Dec 25 19:47:54 volumio volumio[1376]: ---------------------------- MPD announces system playlist update Dec 25 19:47:54 volumio volumio[1376]: info: Ignoring MPD Status Update Dec 25 19:47:54 volumio volumio[1376]: info: Dec 25 19:47:54 volumio volumio[1376]: ---------------------------- MPD announces system playlist update Dec 25 19:47:54 volumio volumio[1376]: info: Ignoring MPD Status Update Dec 25 19:47:54 volumio volumio[1376]: info: ------------------------------ 2ms Dec 25 19:47:54 volumio volumio[1376]: info: sendMpdCommand consume 1 took 2 milliseconds Dec 25 19:47:54 volumio volumio[1376]: info: ------------------------------ 2ms Dec 25 19:47:54 volumio volumio[1376]: info: ------------------------------ 1ms Dec 25 19:47:57 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 25 19:47:57 volumio volumio[1376]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Dec 25 19:47:57 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Dec 25 19:47:57 volumio volumio[1376]: info: Received Get System Version Dec 25 19:47:57 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 25 19:47:57 volumio volumio[1376]: info: Received Get System Info Dec 25 19:47:57 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 25 19:47:57 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 25 19:47:57 volumio volumio[1376]: info: Discovery: Getting this device information Dec 25 19:47:57 volumio volumio[1376]: info: CoreCommandRouter::volumioGetState Dec 25 19:47:57 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 25 19:47:58 volumio volumio[1376]: info: CoreCommandRouter::volumioVolatilePlay Dec 25 19:47:58 volumio volumio[1376]: info: CoreStateMachine::volatilePlay Dec 25 19:47:58 volumio volumio[1376]: info: WARNING: No play method for volatile plugin undefined Dec 25 19:47:59 volumio volumio[1376]: info: CoreStateMachine::startPlaybackTimer Dec 25 19:47:59 volumio volumio[1376]: info: CorePlayQueue::getTrack 1 Dec 25 19:47:59 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:47:59 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:47:59 volumio volumio[1376]: info: Dec 25 19:47:59 volumio volumio[1376]: ---------------------------- MPD announces system playlist update Dec 25 19:47:59 volumio volumio[1376]: info: Ignoring MPD Status Update Dec 25 19:47:59 volumio volumio[1376]: info: Dec 25 19:47:59 volumio volumio[1376]: ---------------------------- MPD announces state update: player Dec 25 19:47:59 volumio volumio[1376]: info: ControllerMpd::getState Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand status Dec 25 19:47:59 volumio volumio[1376]: info: Dec 25 19:47:59 volumio volumio[1376]: ---------------------------- MPD announces system playlist update Dec 25 19:47:59 volumio volumio[1376]: info: Ignoring MPD Status Update Dec 25 19:47:59 volumio volumio[1376]: info: Dec 25 19:47:59 volumio volumio[1376]: ---------------------------- MPD announces state update: player Dec 25 19:47:59 volumio volumio[1376]: info: ControllerMpd::getState Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand status Dec 25 19:47:59 volumio volumio[1376]: info: Dec 25 19:47:59 volumio volumio[1376]: ---------------------------- MPD announces system playlist update Dec 25 19:47:59 volumio volumio[1376]: info: Ignoring MPD Status Update Dec 25 19:47:59 volumio volumio[1376]: info: Dec 25 19:47:59 volumio volumio[1376]: ---------------------------- MPD announces state update: player Dec 25 19:47:59 volumio volumio[1376]: info: ControllerMpd::getState Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand status Dec 25 19:47:59 volumio volumio[1376]: info: ------------------------------ 2ms Dec 25 19:47:59 volumio volumio[1376]: info: sendMpdCommand status took 2 milliseconds Dec 25 19:47:59 volumio volumio[1376]: info: ------------------------------ 2ms Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::parseState Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 25 19:47:59 volumio volumio[1376]: info: sendMpdCommand status took 3 milliseconds Dec 25 19:47:59 volumio volumio[1376]: info: ------------------------------ 2ms Dec 25 19:47:59 volumio volumio[1376]: info: sendMpdCommand status took 2 milliseconds Dec 25 19:47:59 volumio volumio[1376]: info: sendMpdCommand playlistinfo took 2 milliseconds Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::parseState Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::parseState Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::parseTrackInfo Dec 25 19:47:59 volumio volumio[1376]: info: ControllerMpd::pushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreCommandRouter::servicePushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 19:47:59 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:47:59 volumio volumio[1376]: info: ------------------------------ 10ms Dec 25 19:47:59 volumio volumio[1376]: info: sendMpdCommand playlistinfo took 6 milliseconds Dec 25 19:47:59 volumio volumio[1376]: info: sendMpdCommand playlistinfo took 6 milliseconds Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::parseTrackInfo Dec 25 19:47:59 volumio volumio[1376]: verbose: ControllerMpd::parseTrackInfo Dec 25 19:47:59 volumio volumio[1376]: info: ControllerMpd::pushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreCommandRouter::servicePushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:47:59 volumio volumio[1376]: info: ControllerMpd::pushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreCommandRouter::servicePushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:47:59 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:47:59 volumio volumio[1376]: info: ------------------------------ 22ms Dec 25 19:47:59 volumio volumio[1376]: info: ------------------------------ 22ms Dec 25 19:47:59 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:47:59 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:47:59 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:47:59 volumio volumio[1376]: info: touch_display: Setting screensaver timeout to 0 seconds. Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::volumioPause Dec 25 19:48:03 volumio volumio[1376]: info: CoreStateMachine::pause Dec 25 19:48:03 volumio volumio[1376]: info: CoreStateMachine::stPlaybackTimer Dec 25 19:48:03 volumio volumio[1376]: info: CoreStateMachine::servicePause Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::servicePause Dec 25 19:48:03 volumio volumio[1376]: info: ControllerMpd::pause Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand pause Dec 25 19:48:03 volumio volumio[1376]: info: sendMpdCommand pause took 1 milliseconds Dec 25 19:48:03 volumio volumio[1376]: info: Dec 25 19:48:03 volumio volumio[1376]: ---------------------------- MPD announces state update: player Dec 25 19:48:03 volumio volumio[1376]: info: ControllerMpd::getState Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand status Dec 25 19:48:03 volumio volumio[1376]: info: Dec 25 19:48:03 volumio volumio[1376]: ---------------------------- MPD announces state update: player Dec 25 19:48:03 volumio volumio[1376]: info: ControllerMpd::getState Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand status Dec 25 19:48:03 volumio volumio[1376]: info: Dec 25 19:48:03 volumio volumio[1376]: ---------------------------- MPD announces state update: player Dec 25 19:48:03 volumio volumio[1376]: info: ControllerMpd::getState Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand status Dec 25 19:48:03 volumio volumio[1376]: info: sendMpdCommand status took 2 milliseconds Dec 25 19:48:03 volumio volumio[1376]: info: sendMpdCommand status took 2 milliseconds Dec 25 19:48:03 volumio volumio[1376]: info: sendMpdCommand status took 1 milliseconds Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::parseState Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::parseState Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::parseState Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 25 19:48:03 volumio volumio[1376]: info: sendMpdCommand playlistinfo took 2 milliseconds Dec 25 19:48:03 volumio volumio[1376]: info: sendMpdCommand playlistinfo took 2 milliseconds Dec 25 19:48:03 volumio volumio[1376]: info: sendMpdCommand playlistinfo took 1 milliseconds Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::parseTrackInfo Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::parseTrackInfo Dec 25 19:48:03 volumio volumio[1376]: verbose: ControllerMpd::parseTrackInfo Dec 25 19:48:03 volumio volumio[1376]: info: ControllerMpd::pushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::servicePushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:48:03 volumio volumio[1376]: info: ControllerMpd::pushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::servicePushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:48:03 volumio volumio[1376]: info: ControllerMpd::pushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::servicePushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreStateMachine::pushState Dec 25 19:48:03 volumio volumio[1376]: info: CoreCommandRouter::volumioPushState Dec 25 19:48:03 volumio volumio[1376]: info: ------------------------------ 14ms Dec 25 19:48:03 volumio volumio[1376]: info: ------------------------------ 13ms Dec 25 19:48:03 volumio volumio[1376]: info: ------------------------------ 14ms Dec 25 19:48:03 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:48:03 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:48:03 volumio volumio[1376]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Dec 25 19:48:03 volumio volumio[1376]: info: touch_display: Setting screensaver timeout to 120 seconds. Dec 25 19:48:04 volumio volumio[1376]: info: CoreCommandRouter::volumioGetQueue Dec 25 19:48:04 volumio volumio[1376]: info: CoreStateMachine::getQueue Dec 25 19:48:04 volumio volumio[1376]: info: CorePlayQueue::getQueue Dec 25 19:48:06 volumio volumio[1376]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 25 19:48:06 volumio volumio[1376]: info: In handleBrowseUri, curUri=spotify:artist:0xkkLdu91jvvCwEWDPB0PO Dec 25 19:48:21 volumio volumio[1376]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 25 19:48:21 volumio volumio[1376]: TypeError: Cannot read properties of undefined (reading 'url') Dec 25 19:48:21 volumio volumio[1376]: at /data/plugins/music_service/spop/index.js:2449:60 Dec 25 19:48:21 volumio volumio[1376]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Dec 25 19:48:21 volumio volumio[1376]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 25 19:48:22 volumio sudo[1699]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-25 19:47' Dec 25 19:48:22 volumio sudo[1699]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"