-- Logs begin at Thu 2019-02-14 05:11:59 EST, end at Sun 2025-11-02 13:18:46 EST. -- Nov 02 13:17:02 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:02-05:00" level=debug msg="handling skip_next player command from ff81b31374e3b7533230c8d546caa1c5d30dbf7b" Nov 02 13:17:02 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:02-05:00" level=warning msg="failed getting output device delay" error="ALSA error at snd_pcm_delay: Input/output error" Nov 02 13:17:02 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:02-05:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:02 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:02-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:17:02 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:02-05:00" level=trace msg="emitting websocket event: will_play" Nov 02 13:17:02 volumiopizeroto volumio[819]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4esOae7i4rqTbAu9o5Pxco","play_origin":"playlist/ondemand"}} Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="selected format OGG_VORBIS_320 (1ebce7a8727ac70d57b1d54a5c686044e4e4a342)" uri="spotify:track:4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="requested aes key for file 1ebce7a8727ac70d57b1d54a5c686044e4e4a342, gid: 4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=trace msg="found 2 cdn urls" uri="spotify:track:4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="fetched first chunk of 17, total size is 8849640 bytes" uri="spotify:track:4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=info msg="loaded track \"Girl on Fire\" (paused: false, position: 0ms, duration: 224920ms, prefetched: false)" uri="spotify:track:4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=warning msg="failed getting output device delay" error="ALSA error at snd_pcm_delay: Input/output error" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=trace msg="scheduling prefetch in 195s" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=trace msg="emitting websocket event: metadata" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="sending successful reply for dealer request" Nov 02 13:17:03 volumiopizeroto volumio[819]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4esOae7i4rqTbAu9o5Pxco","name":"Girl on Fire","artist_names":["Alicia Keys"],"album_name":"Girl on Fire (Remixes) - EP","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02a4fe49eb27e8152710e7a590","position":0,"duration":224920,"release_date":"year:2012 month:11 day:18","track_number":1,"disc_number":1}} Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=trace msg="emitting websocket event: playing" Nov 02 13:17:03 volumiopizeroto volumio[819]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4esOae7i4rqTbAu9o5Pxco","resume":false,"play_origin":"playlist/ondemand"}} Nov 02 13:17:03 volumiopizeroto volumio[819]: SPOTIFY: PUSH STATE SPOTIFY Nov 02 13:17:03 volumiopizeroto volumio[819]: SPOTIFY: {"status":"play","service":"spop","title":"Girl on Fire","artist":"Alicia Keys","album":"Girl on Fire (Remixes) - EP","albumart":"https://i.scdn.co/image/ab67616d00001e02a4fe49eb27e8152710e7a590","uri":"spotify:track:4esOae7i4rqTbAu9o5Pxco","trackType":"spotify","seek":0,"duration":224,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Nov 02 13:17:03 volumiopizeroto volumio[819]: info: CoreCommandRouter::servicePushState Nov 02 13:17:03 volumiopizeroto volumio[819]: info: CoreStateMachine::pushState Nov 02 13:17:03 volumiopizeroto volumio[819]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 02 13:17:03 volumiopizeroto volumio[819]: info: CoreCommandRouter::volumioPushState Nov 02 13:17:03 volumiopizeroto volumio[819]: info: MRS: Pushing multiroomSync output update for this device Nov 02 13:17:03 volumiopizeroto volumio[819]: info: MRS: Pushing multiroomSync output Nov 02 13:17:03 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:03-05:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:4esOae7i4rqTbAu9o5Pxco" Nov 02 13:17:03 volumiopizeroto volumio[819]: SPOTIFY: PUSH STATE SPOTIFY Nov 02 13:17:03 volumiopizeroto volumio[819]: SPOTIFY: {"status":"play","service":"spop","title":"Girl on Fire","artist":"Alicia Keys","album":"Girl on Fire (Remixes) - EP","albumart":"https://i.scdn.co/image/ab67616d00001e02a4fe49eb27e8152710e7a590","uri":"spotify:track:4esOae7i4rqTbAu9o5Pxco","trackType":"spotify","seek":0,"duration":224,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Nov 02 13:17:03 volumiopizeroto volumio[819]: info: CoreCommandRouter::servicePushState Nov 02 13:17:03 volumiopizeroto volumio[819]: info: CoreStateMachine::pushState Nov 02 13:17:03 volumiopizeroto volumio[819]: info: CoreCommandRouter::volumioPushState Nov 02 13:17:03 volumiopizeroto volumio[819]: info: MRS: Pushing multiroomSync output update for this device Nov 02 13:17:03 volumiopizeroto volumio[819]: info: MRS: Pushing multiroomSync output Nov 02 13:17:06 volumiopizeroto volumio[819]: info: Executing endpoint metavolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: Executing endpoint metavolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: Executing endpoint metavolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: Executing endpoint metavolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: Executing endpoint metavolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: Executing endpoint metavolumio Nov 02 13:17:06 volumiopizeroto volumio[819]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 02 13:17:07 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:07-05:00" level=debug msg="update volume requested to 47840/65535" Nov 02 13:17:07 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:07-05:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 02 13:17:07 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:07-05:00" level=trace msg="emitting websocket event: volume" Nov 02 13:17:07 volumiopizeroto volumio[819]: SPOTIFY: received: {"type":"volume","data":{"value":73,"max":100}} Nov 02 13:17:07 volumiopizeroto volumio[819]: SPOTIFY: RECEIVED SPOTIFY VOLUME 73 Nov 02 13:17:07 volumiopizeroto volumio[819]: info: Setting Volumio Volume from Spotify: 73 Nov 02 13:17:07 volumiopizeroto volumio[819]: info: VolumeController::SetAlsaVolume73 Nov 02 13:17:07 volumiopizeroto volumio[819]: info: CoreStateMachine::pushState Nov 02 13:17:07 volumiopizeroto volumio[819]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 02 13:17:07 volumiopizeroto volumio[819]: info: CoreCommandRouter::volumioPushState Nov 02 13:17:07 volumiopizeroto volumio[819]: info: MRS: Pushing multiroomSync output update for this device Nov 02 13:17:07 volumiopizeroto volumio[819]: info: MRS: Pushing multiroomSync output Nov 02 13:17:08 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:08-05:00" level=debug msg="update volume requested to 49806/65535" Nov 02 13:17:08 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:08-05:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 02 13:17:08 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:08-05:00" level=trace msg="emitting websocket event: volume" Nov 02 13:17:08 volumiopizeroto volumio[819]: SPOTIFY: received: {"type":"volume","data":{"value":76,"max":100}} Nov 02 13:17:08 volumiopizeroto volumio[819]: SPOTIFY: RECEIVED SPOTIFY VOLUME 76 Nov 02 13:17:08 volumiopizeroto volumio[819]: info: Setting Volumio Volume from Spotify: 76 Nov 02 13:17:08 volumiopizeroto volumio[819]: info: VolumeController::SetAlsaVolume76 Nov 02 13:17:08 volumiopizeroto volumio[819]: info: CoreStateMachine::pushState Nov 02 13:17:08 volumiopizeroto volumio[819]: info: CoreCommandRouter::volumioPushState Nov 02 13:17:08 volumiopizeroto volumio[819]: info: MRS: Pushing multiroomSync output update for this device Nov 02 13:17:08 volumiopizeroto volumio[819]: info: MRS: Pushing multiroomSync output Nov 02 13:17:25 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:25-05:00" level=trace msg="sent dealer ping" Nov 02 13:17:25 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:25-05:00" level=trace msg="received dealer pong" Nov 02 13:17:55 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:55-05:00" level=trace msg="sent dealer ping" Nov 02 13:17:55 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:17:55-05:00" level=trace msg="received dealer pong" Nov 02 13:18:25 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:18:25-05:00" level=trace msg="received accesspoint ping" Nov 02 13:18:25 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:18:25-05:00" level=trace msg="received accesspoint pong ack" Nov 02 13:18:25 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:18:25-05:00" level=trace msg="sent dealer ping" Nov 02 13:18:25 volumiopizeroto go-librespot[1036]: time="2025-11-02T13:18:25-05:00" level=trace msg="received dealer pong" Nov 02 13:18:45 volumiopizeroto volumio[819]: info: [1762107525284] [80s80s] Pushing the next song state Howard Jones - What Is Love? and getting next track. Nov 02 13:18:45 volumiopizeroto volumio[819]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 02 13:18:45 volumiopizeroto volumio[819]: TypeError: Cannot set property 'name' of undefined Nov 02 13:18:45 volumiopizeroto volumio[819]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Nov 02 13:18:45 volumiopizeroto volumio[819]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Nov 02 13:18:45 volumiopizeroto volumio[819]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Nov 02 13:18:45 volumiopizeroto volumio[819]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Nov 02 13:18:45 volumiopizeroto volumio[819]: at processImmediate (internal/timers.js:461:21) Nov 02 13:18:45 volumiopizeroto volumio[819]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 02 13:18:46 volumiopizeroto sudo[31752]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-11-02 13:17 Nov 02 13:18:46 volumiopizeroto sudo[31752]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"