-- Logs begin at Sun 2025-04-20 11:09:26 KST, end at Tue 2025-04-22 19:52:39 KST. -- Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=trace msg="emitting websocket event: not_playing" Apr 22 19:51:07 volumio volumio[827]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:7M97mADSOdA5wVDsOzbHSe","play_origin":"artist"}} Apr 22 19:51:07 volumio volumio[827]: error: Failed to decode event: not_playing Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6Fa7jv1as1tA7JGdt7UKCp" Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=trace msg="emitting websocket event: will_play" Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=info msg="loaded track \"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione\" (paused: false, position: 0ms, duration: 197026ms, prefetched: true)" uri="spotify:track:6Fa7jv1as1tA7JGdt7UKCp" Apr 22 19:51:07 volumio volumio[827]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","play_origin":"artist"}} Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=trace msg="scheduling prefetch in 167s" Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=trace msg="emitting websocket event: metadata" Apr 22 19:51:07 volumio volumio[827]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","name":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist_names":["Ludwig van Beethoven","Minsoo Sohn"],"album_name":"Beethoven Complete Piano Sonatas","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","position":0,"duration":197026,"release_date":"year:2020 month:9 day:11","track_number":11,"disc_number":4}} Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:51:07 volumio go-librespot[1186]: time="2025-04-22T19:51:07+09:00" level=trace msg="emitting websocket event: playing" Apr 22 19:51:07 volumio volumio[827]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","play_origin":"artist"}} Apr 22 19:51:07 volumio volumio[827]: SPOTIFY: PUSH STATE SPOTIFY Apr 22 19:51:07 volumio volumio[827]: SPOTIFY: {"status":"play","service":"spop","title":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist":"Ludwig van Beethoven, Minsoo Sohn","album":"Beethoven Complete Piano Sonatas","albumart":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","trackType":"spotify","seek":0,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":false,"repeatSingle":false,"stream":false,"repeatMode":"all"} Apr 22 19:51:07 volumio volumio[827]: info: CoreCommandRouter::servicePushState Apr 22 19:51:07 volumio volumio[827]: info: CoreStateMachine::pushState Apr 22 19:51:07 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 19:51:07 volumio volumio[827]: info: CoreCommandRouter::volumioPushState Apr 22 19:51:07 volumio volumio[827]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Apr 22 19:51:08 volumio volumio[827]: SPOTIFY: PUSH STATE SPOTIFY Apr 22 19:51:08 volumio volumio[827]: SPOTIFY: {"status":"play","service":"spop","title":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist":"Ludwig van Beethoven, Minsoo Sohn","album":"Beethoven Complete Piano Sonatas","albumart":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","trackType":"spotify","seek":0,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":false,"repeatSingle":false,"stream":false,"repeatMode":"all"} Apr 22 19:51:08 volumio volumio[827]: info: CoreCommandRouter::servicePushState Apr 22 19:51:08 volumio volumio[827]: info: CoreStateMachine::pushState Apr 22 19:51:08 volumio volumio[827]: info: CoreCommandRouter::volumioPushState Apr 22 19:51:08 volumio volumio[827]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Apr 22 19:51:22 volumio go-librespot[1186]: time="2025-04-22T19:51:22+09:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:6Fa7jv1as1tA7JGdt7UKCp" Apr 22 19:51:23 volumio go-librespot[1186]: time="2025-04-22T19:51:23+09:00" level=trace msg="sent dealer ping" Apr 22 19:51:23 volumio go-librespot[1186]: time="2025-04-22T19:51:23+09:00" level=trace msg="received dealer pong" Apr 22 19:51:29 volumio sudo[26494]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 22 19:51:29 volumio sudo[26492]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 22 19:51:29 volumio sudo[26494]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 19:51:29 volumio sudo[26492]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 19:51:29 volumio sudo[26494]: pam_unix(sudo:session): session closed for user root Apr 22 19:51:29 volumio sudo[26492]: pam_unix(sudo:session): session closed for user root Apr 22 19:51:29 volumio volumio[827]: verbose: New Socket.io Connection to 192.168.0.8 from 192.168.0.2 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Apr 22 19:51:30 volumio volumio[827]: info: CoreCommandRouter::volumioGetVisibleSources Apr 22 19:51:30 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 22 19:51:30 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 22 19:51:30 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Apr 22 19:51:30 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 22 19:51:30 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 22 19:51:30 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 22 19:51:30 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 22 19:51:30 volumio sudo[26501]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 22 19:51:30 volumio sudo[26501]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 19:51:31 volumio sudo[26503]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 22 19:51:31 volumio sudo[26503]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 22 19:51:31 volumio sudo[26503]: pam_unix(sudo:session): session closed for user root Apr 22 19:51:31 volumio sudo[26501]: pam_unix(sudo:session): session closed for user root Apr 22 19:51:31 volumio volumio[827]: verbose: New Socket.io Connection to 192.168.0.8 from 192.168.0.2 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Apr 22 19:51:31 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Apr 22 19:51:31 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 22 19:51:31 volumio volumio[827]: info: CoreCommandRouter::volumioGetVisibleSources Apr 22 19:51:31 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 22 19:51:31 volumio volumio[827]: info: Listing playlists Apr 22 19:51:31 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 22 19:51:31 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 22 19:51:31 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 22 19:51:31 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 22 19:51:34 volumio volumio[827]: info: Received Get System Info Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 22 19:51:34 volumio volumio[827]: info: Discovery: Getting this device information Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 22 19:51:34 volumio volumio[827]: info: Received Get System Info Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 22 19:51:34 volumio volumio[827]: info: Discovery: Getting this device information Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 22 19:51:34 volumio volumio[827]: info: CoreCommandRouter::volumioGetQueue Apr 22 19:51:34 volumio volumio[827]: info: CoreStateMachine::getQueue Apr 22 19:51:34 volumio volumio[827]: info: CorePlayQueue::getQueue Apr 22 19:51:37 volumio go-librespot[1186]: time="2025-04-22T19:51:37+09:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:6Fa7jv1as1tA7JGdt7UKCp" Apr 22 19:51:39 volumio volumio[827]: info: CoreCommandRouter::volumioRemoveQueueItem Apr 22 19:51:39 volumio volumio[827]: info: CoreStateMachine::removeQueueItem Apr 22 19:51:40 volumio volumio[827]: info: CoreStateMachine::stop Apr 22 19:51:40 volumio volumio[827]: info: CoreStateMachine::serviceStop Apr 22 19:51:40 volumio volumio[827]: info: CoreCommandRouter::serviceStop Apr 22 19:51:40 volumio volumio[827]: info: Spotify Stop Apr 22 19:51:40 volumio volumio[827]: SPOTIFY: SPOTIFY STOP Apr 22 19:51:40 volumio volumio[827]: SPOTIFY: {"status":"play","title":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist":"Ludwig van Beethoven, Minsoo Sohn","album":"Beethoven Complete Piano Sonatas","albumart":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","trackType":"spotify","codec":"ogg","seek":0,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":"10","dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Apr 22 19:51:40 volumio volumio[827]: info: Sending Spotify command to local API: /player/pause Apr 22 19:51:40 volumio volumio[827]: info: CorePlayQueue::removeQueueItem 0 Apr 22 19:51:40 volumio volumio[827]: info: CorePlayQueue::saveQueue Apr 22 19:51:40 volumio volumio[827]: info: CoreCommandRouter::volumioPushQueue Apr 22 19:51:40 volumio go-librespot[1186]: time="2025-04-22T19:51:40+09:00" level=debug msg="pause track at 32424ms" Apr 22 19:51:40 volumio go-librespot[1186]: time="2025-04-22T19:51:40+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:51:40 volumio go-librespot[1186]: time="2025-04-22T19:51:40+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:51:40 volumio go-librespot[1186]: time="2025-04-22T19:51:40+09:00" level=trace msg="emitting websocket event: paused" Apr 22 19:51:40 volumio volumio[827]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","play_origin":"artist"}} Apr 22 19:51:40 volumio volumio[827]: SPOTIFY: PUSH STATE SPOTIFY Apr 22 19:51:40 volumio volumio[827]: SPOTIFY: {"status":"pause","service":"spop","title":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist":"Ludwig van Beethoven, Minsoo Sohn","album":"Beethoven Complete Piano Sonatas","albumart":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","trackType":"spotify","seek":32000,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":false,"repeatSingle":false,"stream":false,"repeatMode":"all"} Apr 22 19:51:40 volumio volumio[827]: info: CoreCommandRouter::servicePushState Apr 22 19:51:40 volumio volumio[827]: info: CoreStateMachine::pushState Apr 22 19:51:40 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 19:51:40 volumio volumio[827]: info: CoreCommandRouter::volumioPushState Apr 22 19:51:40 volumio volumio[827]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Apr 22 19:51:48 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Apr 22 19:51:48 volumio volumio[827]: info: In handleBrowseUri, curUri=spotify Apr 22 19:51:49 volumio volumio[827]: info: New access token = BQCGNNn6E0fjy_7EgHc4PO-RY_ibzWkXwqa1SdNxP8FBXmnA6zPGVl2y9-bO2MRbPi9bL6V4UfuryH86jc7UMJCM6UlRIEdnXnlu9tKhfWsxmmsEvMGUXWpVyuzGp70fErX7_Q2vUwzBhTmBJftSLU6uVt9_3oT0dcWKKsbAQZhwVvDv9I-zN9u-K7YJofEymdqJ-QPs_Mqn5LK1xaURL4lzCa0FknKMHaVbhkeRxEzwNNPniGvbc9HFz6FYm4fckBD-KeNHeNk3fdjlGHPcw3SJgov2b98WmJ0h_59OdQ0bpSs Apr 22 19:51:49 volumio volumio[827]: info: New access token = BQBu57nqnIzJoKiwR6nVkY8CPHdh7Bm9nZ_Q1ck1JLliLhpyj5GkEiqiBQ0qAmYMonjBIbad5aH2B4F-pDsfTc-4F9WZB_QoWAepEWOzgQUGKkt3ykHO6sGOjbQ46HxqkllS0Q4KRLlXNBWlaQZlFOO5RRMbyqjUlMM5xiopM5M-JxX1lUMkFbKk7qhz9JuXG0nJMLf1cjc1qcisbZbahhlKmfJRd-6e0sZlzDGpcinaDdF2U__yjjzUTjALjHJO2qji3rqPGcvenbrgB1zPDaQMbHuomsMt-LUovl2cL6Et1Xc Apr 22 19:51:49 volumio volumio[827]: info: New access token = BQBc_iDlMpRdBv00Qi1WCy1kST-mg1i-IH9YX0pCrDrOz5oMvgRJ2PTupNc5j3YwCQFIaJoPx4iFaqV3jv-cAF8pIR6m9rgg2NPZJXNO1HVIn0gi_HCk81woBrJc9QANfW1RgutTFQ2NTAd4gLYdK95BL7zKw8UzFcckeiYbV32iKTERqBP9VvpMxjIrPwzozStbKlEfiUYgGRb15C7RlS-CTdFgc1AlNZnchQ6A55M-15pmQyUapswL_Kra14brRZtcsZYblaEWWvPRVQ5kQUUPi984GJEna-0mONN-1CpKoq4 Apr 22 19:51:49 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 22 19:51:49 volumio volumio[827]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 22 19:51:49 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 22 19:51:49 volumio volumio[827]: info: Received Get System Version Apr 22 19:51:49 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 22 19:51:49 volumio volumio[827]: info: Received Get System Info Apr 22 19:51:49 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 22 19:51:49 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 22 19:51:49 volumio volumio[827]: info: Discovery: Getting this device information Apr 22 19:51:49 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Apr 22 19:51:49 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 22 19:51:50 volumio volumio[827]: info: Preload queue cleared Apr 22 19:51:50 volumio volumio[827]: info: Preload queue cleared Apr 22 19:51:53 volumio go-librespot[1186]: time="2025-04-22T19:51:53+09:00" level=trace msg="sent dealer ping" Apr 22 19:51:53 volumio go-librespot[1186]: time="2025-04-22T19:51:53+09:00" level=trace msg="received dealer pong" Apr 22 19:52:01 volumio volumio[827]: info: CoreCommandRouter::volumioVolatilePlay Apr 22 19:52:01 volumio volumio[827]: info: CoreStateMachine::volatilePlay Apr 22 19:52:01 volumio volumio[827]: info: Spotify Play Apr 22 19:52:01 volumio volumio[827]: info: Sending Spotify command to local API: /player/resume Apr 22 19:52:01 volumio go-librespot[1186]: time="2025-04-22T19:52:01+09:00" level=trace msg="seek to 32424ms (diff: 153ms, samples: 1429898, bytes: 1128864)" uri="spotify:track:6Fa7jv1as1tA7JGdt7UKCp" Apr 22 19:52:01 volumio go-librespot[1186]: time="2025-04-22T19:52:01+09:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Apr 22 19:52:01 volumio go-librespot[1186]: time="2025-04-22T19:52:01+09:00" level=debug msg="resume track at 32271ms" Apr 22 19:52:01 volumio go-librespot[1186]: time="2025-04-22T19:52:01+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:52:01 volumio go-librespot[1186]: time="2025-04-22T19:52:01+09:00" level=trace msg="scheduling prefetch in 135s" Apr 22 19:52:01 volumio go-librespot[1186]: time="2025-04-22T19:52:01+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:52:01 volumio go-librespot[1186]: time="2025-04-22T19:52:01+09:00" level=trace msg="emitting websocket event: playing" Apr 22 19:52:01 volumio volumio[827]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","play_origin":"artist"}} Apr 22 19:52:01 volumio volumio[827]: SPOTIFY: PUSH STATE SPOTIFY Apr 22 19:52:01 volumio volumio[827]: SPOTIFY: {"status":"play","service":"spop","title":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist":"Ludwig van Beethoven, Minsoo Sohn","album":"Beethoven Complete Piano Sonatas","albumart":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","trackType":"spotify","seek":32000,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":false,"repeatSingle":false,"stream":false,"repeatMode":"all"} Apr 22 19:52:01 volumio volumio[827]: info: CoreCommandRouter::servicePushState Apr 22 19:52:01 volumio volumio[827]: info: CoreStateMachine::pushState Apr 22 19:52:01 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 19:52:01 volumio volumio[827]: info: CoreCommandRouter::volumioPushState Apr 22 19:52:01 volumio volumio[827]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Apr 22 19:52:01 volumio volumio[827]: SPOTIFY: PUSH STATE SPOTIFY Apr 22 19:52:01 volumio volumio[827]: SPOTIFY: {"status":"play","service":"spop","title":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist":"Ludwig van Beethoven, Minsoo Sohn","album":"Beethoven Complete Piano Sonatas","albumart":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","trackType":"spotify","seek":32000,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":false,"repeatSingle":false,"stream":false,"repeatMode":"all"} Apr 22 19:52:01 volumio volumio[827]: info: CoreCommandRouter::servicePushState Apr 22 19:52:01 volumio volumio[827]: info: CoreStateMachine::pushState Apr 22 19:52:01 volumio volumio[827]: info: CoreCommandRouter::volumioPushState Apr 22 19:52:02 volumio volumio[827]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Apr 22 19:52:14 volumio go-librespot[1186]: time="2025-04-22T19:52:14+09:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:6Fa7jv1as1tA7JGdt7UKCp" Apr 22 19:52:16 volumio volumio[827]: info: CoreCommandRouter::volumioPause Apr 22 19:52:16 volumio volumio[827]: info: CoreStateMachine::pause Apr 22 19:52:16 volumio volumio[827]: info: CoreStateMachine::stPlaybackTimer Apr 22 19:52:16 volumio volumio[827]: info: CoreStateMachine::servicePause Apr 22 19:52:16 volumio volumio[827]: info: CoreCommandRouter::servicePause Apr 22 19:52:16 volumio volumio[827]: info: Spotify Received pause Apr 22 19:52:16 volumio volumio[827]: SPOTIFY: SPOTIFY PAUSE Apr 22 19:52:16 volumio volumio[827]: SPOTIFY: {"status":"play","title":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist":"Ludwig van Beethoven, Minsoo Sohn","album":"Beethoven Complete Piano Sonatas","albumart":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","trackType":"spotify","codec":"ogg","seek":32000,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":true,"repeat":false,"repeatSingle":false,"consume":false,"volume":"10","dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Apr 22 19:52:16 volumio volumio[827]: info: Sending Spotify command to local API: /player/pause Apr 22 19:52:16 volumio go-librespot[1186]: time="2025-04-22T19:52:16+09:00" level=debug msg="pause track at 47245ms" Apr 22 19:52:16 volumio go-librespot[1186]: time="2025-04-22T19:52:16+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:52:16 volumio go-librespot[1186]: time="2025-04-22T19:52:16+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 22 19:52:16 volumio go-librespot[1186]: time="2025-04-22T19:52:16+09:00" level=trace msg="emitting websocket event: paused" Apr 22 19:52:16 volumio volumio[827]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","play_origin":"artist"}} Apr 22 19:52:16 volumio volumio[827]: SPOTIFY: PUSH STATE SPOTIFY Apr 22 19:52:16 volumio volumio[827]: SPOTIFY: {"status":"pause","service":"spop","title":"Sonata No. 13 in E-Flat Major, Op. 27 No. 1 III. Adagio con espressione","artist":"Ludwig van Beethoven, Minsoo Sohn","album":"Beethoven Complete Piano Sonatas","albumart":"https://i.scdn.co/image/ab67616d00001e02433491bde16569b3041a5cab","uri":"spotify:track:6Fa7jv1as1tA7JGdt7UKCp","trackType":"spotify","seek":47000,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":false,"repeatSingle":false,"stream":false,"repeatMode":"all"} Apr 22 19:52:16 volumio volumio[827]: info: CoreCommandRouter::servicePushState Apr 22 19:52:16 volumio volumio[827]: info: CoreStateMachine::pushState Apr 22 19:52:16 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 22 19:52:16 volumio volumio[827]: info: CoreCommandRouter::volumioPushState Apr 22 19:52:16 volumio volumio[827]: SPOTIFY: RECEIVED VOLUMIO VOLUME 10 Apr 22 19:52:20 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Apr 22 19:52:20 volumio volumio[827]: info: Preload queue cleared Apr 22 19:52:23 volumio go-librespot[1186]: time="2025-04-22T19:52:23+09:00" level=trace msg="received accesspoint ping" Apr 22 19:52:23 volumio go-librespot[1186]: time="2025-04-22T19:52:23+09:00" level=trace msg="received accesspoint pong ack" Apr 22 19:52:23 volumio go-librespot[1186]: time="2025-04-22T19:52:23+09:00" level=trace msg="sent dealer ping" Apr 22 19:52:23 volumio go-librespot[1186]: time="2025-04-22T19:52:23+09:00" level=trace msg="received dealer pong" Apr 22 19:52:24 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Apr 22 19:52:27 volumio volumio[827]: info: Preload queue cleared Apr 22 19:52:28 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Apr 22 19:52:29 volumio volumio[827]: info: Preload queue cleared Apr 22 19:52:32 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Apr 22 19:52:32 volumio volumio[827]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 22 19:52:32 volumio volumio[827]: TypeError: Cannot read property 'length' of undefined Apr 22 19:52:32 volumio volumio[827]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Apr 22 19:52:32 volumio volumio[827]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Apr 22 19:52:32 volumio volumio[827]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Apr 22 19:52:32 volumio volumio[827]: at Parser.emit (events.js:315:20) Apr 22 19:52:32 volumio volumio[827]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Apr 22 19:52:32 volumio volumio[827]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Apr 22 19:52:32 volumio volumio[827]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Apr 22 19:52:32 volumio volumio[827]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Apr 22 19:52:32 volumio volumio[827]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Apr 22 19:52:32 volumio volumio[827]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Apr 22 19:52:32 volumio volumio[827]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Apr 22 19:52:32 volumio volumio[827]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Apr 22 19:52:32 volumio volumio[827]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Apr 22 19:52:32 volumio volumio[827]: at IncomingMessage.emit (events.js:327:22) Apr 22 19:52:32 volumio volumio[827]: at endReadableNT (internal/streams/readable.js:1327:12) Apr 22 19:52:32 volumio volumio[827]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Apr 22 19:52:33 volumio volumio[827]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 22 19:52:39 volumio sudo[26665]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-22 19:51 Apr 22 19:52:39 volumio sudo[26665]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"