-- Journal begins at Sat 2025-07-05 11:19:45 UTC, ends at Sun 2025-07-06 12:54:36 UTC. -- Jul 06 12:53:02 volpi go-librespot[1169]: time="2025-07-06T12:53:02Z" level=debug msg="fetched chunk 21/23, size: 524288" uri="spotify:track:4osgfFTICMkcGbbigdsa53" Jul 06 12:53:03 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:53:03 volpi volumio[998]: info: Listing playlists Jul 06 12:53:03 volpi volumio[998]: info: Listing playlists Jul 06 12:53:13 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:53:16 volpi go-librespot[1169]: time="2025-07-06T12:53:16Z" level=debug msg="fetched chunk 22/23, size: 524288" uri="spotify:track:4osgfFTICMkcGbbigdsa53" Jul 06 12:53:23 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:53:23 volpi volumio[998]: info: Listing playlists Jul 06 12:53:23 volpi volumio[998]: info: Listing playlists Jul 06 12:53:29 volpi go-librespot[1169]: time="2025-07-06T12:53:29Z" level=debug msg="fetched chunk 23/23, size: 509524" uri="spotify:track:4osgfFTICMkcGbbigdsa53" Jul 06 12:53:33 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:53:43 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:53:43 volpi volumio[998]: info: Listing playlists Jul 06 12:53:43 volpi volumio[998]: info: Listing playlists Jul 06 12:53:53 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=debug msg="prefetching next track" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=debug msg="selected format OGG_VORBIS_320 (1fa4049ef2e96c7bc5229d592379fe6b4020f90b)" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=debug msg="requested aes key for file 1fa4049ef2e96c7bc5229d592379fe6b4020f90b, gid: 2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=debug msg="fetched first chunk of 18, total size is 9034580 bytes" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=info msg="prefetched track \"Tokyo Drifting\" (duration: 216821ms)" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:53:54 volpi go-librespot[1169]: time="2025-07-06T12:53:54Z" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:54:03 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:54:03 volpi volumio[998]: info: Listing playlists Jul 06 12:54:03 volpi volumio[998]: info: Listing playlists Jul 06 12:54:13 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:54:23 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:54:23 volpi volumio[998]: info: Listing playlists Jul 06 12:54:23 volpi volumio[998]: info: Listing playlists Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=trace msg="emitting websocket event: not_playing" Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:4osgfFTICMkcGbbigdsa53","play_origin":"playlist/ondemand"}} Jul 06 12:54:23 volpi volumio[998]: error: Failed to decode event: not_playing Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=trace msg="emitting websocket event: will_play" Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2MA6YoaFF7fnWqkuOAWjUg","play_origin":"playlist/ondemand"}} Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=info msg="loaded track \"Tokyo Drifting\" (paused: false, position: 0ms, duration: 216821ms, prefetched: true)" uri="spotify:track:2MA6YoaFF7fnWqkuOAWjUg" Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=trace msg="scheduling prefetch in 187s" Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=trace msg="emitting websocket event: metadata" Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2MA6YoaFF7fnWqkuOAWjUg","name":"Tokyo Drifting","artist_names":["Glass Animals","Denzel Curry"],"album_name":"Dreamland","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02712701c5e263efc8726b1464","position":0,"duration":216821,"release_date":"year:2020 month:8 day:7","track_number":7,"disc_number":1}} Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 06 12:54:23 volpi go-librespot[1169]: time="2025-07-06T12:54:23Z" level=trace msg="emitting websocket event: playing" Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2MA6YoaFF7fnWqkuOAWjUg","play_origin":"playlist/ondemand"}} Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: PUSH STATE SPOTIFY Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: {"status":"play","service":"spop","title":"Tokyo Drifting","artist":"Glass Animals, Denzel Curry","album":"Dreamland","albumart":"https://i.scdn.co/image/ab67616d00001e02712701c5e263efc8726b1464","uri":"spotify:track:2MA6YoaFF7fnWqkuOAWjUg","trackType":"spotify","seek":0,"duration":216,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jul 06 12:54:23 volpi volumio[998]: info: CoreCommandRouter::servicePushState Jul 06 12:54:23 volpi volumio[998]: info: CoreStateMachine::pushState Jul 06 12:54:23 volpi volumio[998]: info: CoreCommandRouter::volumioPushState Jul 06 12:54:23 volpi volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 06 12:54:23 volpi volumio[998]: [AmpSwitch] CurStatus: play PrevStatus: play Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: PUSH STATE SPOTIFY Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: {"status":"play","service":"spop","title":"Tokyo Drifting","artist":"Glass Animals, Denzel Curry","album":"Dreamland","albumart":"https://i.scdn.co/image/ab67616d00001e02712701c5e263efc8726b1464","uri":"spotify:track:2MA6YoaFF7fnWqkuOAWjUg","trackType":"spotify","seek":0,"duration":216,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jul 06 12:54:23 volpi volumio[998]: info: CoreCommandRouter::servicePushState Jul 06 12:54:23 volpi volumio[998]: info: CoreStateMachine::pushState Jul 06 12:54:23 volpi volumio[998]: info: CoreCommandRouter::volumioPushState Jul 06 12:54:23 volpi volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 06 12:54:23 volpi volumio[998]: [AmpSwitch] CurStatus: play PrevStatus: play Jul 06 12:54:23 volpi volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Jul 06 12:54:29 volpi irexec[16519]: {"time":1751744769215,"response":"toggle Success"} Jul 06 12:54:29 volpi irexec[28037]: % Total % Received % Xferd Average Speed Time Time Time Current Jul 06 12:54:29 volpi irexec[28037]: Dload Upload Total Spent Left Speed Jul 06 12:54:29 volpi volumio[998]: info: Jul 06 12:54:29 volpi volumio[998]: ---------------------------- Client requests Volumio toggle Jul 06 12:54:29 volpi volumio[998]: info: CoreCommandRouter::volumioToggle Jul 06 12:54:29 volpi volumio[998]: info: CoreStateMachine::pause Jul 06 12:54:29 volpi volumio[998]: info: CoreStateMachine::stPlaybackTimer Jul 06 12:54:29 volpi volumio[998]: info: CoreStateMachine::servicePause Jul 06 12:54:29 volpi volumio[998]: info: CoreCommandRouter::servicePause Jul 06 12:54:29 volpi volumio[998]: info: Spotify Received pause Jul 06 12:54:29 volpi volumio[998]: SPOTIFY: SPOTIFY PAUSE Jul 06 12:54:29 volpi volumio[998]: SPOTIFY: {"status":"play","title":"Tokyo Drifting","artist":"Glass Animals, Denzel Curry","album":"Dreamland","albumart":"https://i.scdn.co/image/ab67616d00001e02712701c5e263efc8726b1464","uri":"spotify:track:2MA6YoaFF7fnWqkuOAWjUg","trackType":"spotify","seek":0,"duration":216,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":true,"repeat":null,"repeatSingle":null,"consume":false,"volume":41,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Jul 06 12:54:29 volpi volumio[998]: info: Sending Spotify command to local API: /player/pause Jul 06 12:54:29 volpi irexec[28037]: [158B blob data] Jul 06 12:54:29 volpi go-librespot[1169]: time="2025-07-06T12:54:29Z" level=debug msg="pause track at 5821ms" Jul 06 12:54:29 volpi go-librespot[1169]: time="2025-07-06T12:54:29Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 06 12:54:29 volpi go-librespot[1169]: time="2025-07-06T12:54:29Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 06 12:54:29 volpi go-librespot[1169]: time="2025-07-06T12:54:29Z" level=trace msg="emitting websocket event: paused" Jul 06 12:54:29 volpi volumio[998]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:2MA6YoaFF7fnWqkuOAWjUg","play_origin":"playlist/ondemand"}} Jul 06 12:54:29 volpi volumio[998]: SPOTIFY: PUSH STATE SPOTIFY Jul 06 12:54:29 volpi volumio[998]: SPOTIFY: {"status":"pause","service":"spop","title":"Tokyo Drifting","artist":"Glass Animals, Denzel Curry","album":"Dreamland","albumart":"https://i.scdn.co/image/ab67616d00001e02712701c5e263efc8726b1464","uri":"spotify:track:2MA6YoaFF7fnWqkuOAWjUg","trackType":"spotify","seek":5000,"duration":216,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":true,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jul 06 12:54:29 volpi volumio[998]: info: CoreCommandRouter::servicePushState Jul 06 12:54:29 volpi volumio[998]: info: CoreStateMachine::pushState Jul 06 12:54:29 volpi volumio[998]: info: CoreCommandRouter::volumioPushState Jul 06 12:54:29 volpi volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 06 12:54:29 volpi volumio[998]: [AmpSwitch] CurStatus: pause PrevStatus: play Jul 06 12:54:29 volpi volumio[998]: [AmpSwitch] InitTimeout - Amp off in: 720 ms Jul 06 12:54:29 volpi volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Jul 06 12:54:30 volpi volumio[998]: [AmpSwitch] Toggle: OFF: GPIO: HIGH Jul 06 12:54:33 volpi volumio[998]: info: CoreCommandRouter::volumioGetState Jul 06 12:54:35 volpi irexec[28037]: {"time":1751806469166,"response":"toggle Success"} Jul 06 12:54:35 volpi irexec[28041]: % Total % Received % Xferd Average Speed Time Time Time Current Jul 06 12:54:35 volpi irexec[28041]: Dload Upload Total Spent Left Speed Jul 06 12:54:35 volpi volumio[998]: info: Jul 06 12:54:35 volpi volumio[998]: ---------------------------- Client requests Volumio toggle Jul 06 12:54:35 volpi volumio[998]: info: CoreCommandRouter::volumioToggle Jul 06 12:54:35 volpi volumio[998]: info: CoreStateMachine::play index undefined Jul 06 12:54:35 volpi volumio[998]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 06 12:54:35 volpi volumio[998]: info: CorePlayQueue::getTrack 0 Jul 06 12:54:35 volpi volumio[998]: info: CoreStateMachine::startPlaybackTimer Jul 06 12:54:35 volpi volumio[998]: info: CorePlayQueue::getTrack 0 Jul 06 12:54:35 volpi volumio[998]: verbose: ControllerMpd::sendMpdCommand play Jul 06 12:54:35 volpi irexec[28041]: [158B blob data] Jul 06 12:54:35 volpi volumio[998]: info: CoreCommandRouter::servicePushState Jul 06 12:54:35 volpi volumio[998]: info: CoreStateMachine::pushState Jul 06 12:54:35 volpi volumio[998]: info: CoreCommandRouter::volumioPushState Jul 06 12:54:35 volpi volumio[998]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 06 12:54:35 volpi volumio[998]: [AmpSwitch] CurStatus: play PrevStatus: pause Jul 06 12:54:35 volpi volumio[998]: [AmpSwitch] Toggle: ON: GPIO: LOW Jul 06 12:54:35 volpi volumio[998]: info: [1751806475817] [RadioParadise] getMetadata started with url undefined Jul 06 12:54:35 volpi volumio[998]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Jul 06 12:54:35 volpi volumio[998]: info: [1751806475829] [RadioParadise] Error: connect ECONNREFUSED 127.0.0.1:443 Jul 06 12:54:35 volpi volumio[998]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 06 12:54:35 volpi volumio[998]: TypeError: Cannot read property 'toUpperCase' of undefined Jul 06 12:54:35 volpi volumio[998]: at ControllerRadioParadise.errorToast (/data/plugins/music_service/radio_paradise/index.js:481:41) Jul 06 12:54:35 volpi volumio[998]: at ClientRequest. (/data/plugins/music_service/radio_paradise/index.js:452:14) Jul 06 12:54:35 volpi volumio[998]: at ClientRequest.emit (events.js:400:28) Jul 06 12:54:35 volpi volumio[998]: at TLSSocket.socketErrorListener (_http_client.js:475:9) Jul 06 12:54:35 volpi volumio[998]: at TLSSocket.emit (events.js:400:28) Jul 06 12:54:35 volpi volumio[998]: at emitErrorNT (internal/streams/destroy.js:106:8) Jul 06 12:54:35 volpi volumio[998]: at emitErrorCloseNT (internal/streams/destroy.js:74:3) Jul 06 12:54:35 volpi volumio[998]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Jul 06 12:54:35 volpi volumio[998]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 06 12:54:36 volpi sudo[28051]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-06 12:53 Jul 06 12:54:36 volpi sudo[28051]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 11 (bullseye)" NAME="Raspbian GNU/Linux" VERSION_ID="11" VERSION="11 (bullseye)" VERSION_CODENAME=bullseye 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="f8cee3f9fa8056483a9fe34c7e84ec0ad63dbf7f" VOLUMIO_FE_VERSION="77db3ca2a7f5a7023ece8c5b86e997d58abdace6" VOLUMIO_FE3_VERSION="0901de3b023cbd0c160f97c7c282daa9512154d0" VOLUMIO_BE_VERSION="37f54cd4b894db041dfee26290d5bfd8a2e06744" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Jul 16 16:10:12 UTC 2021" VOLUMIO_VERSION="3.020" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="ca65458b47c33089422798176e31bc56"