Dec 12 22:50:04 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:04 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:05 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:06 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:06 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:07 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:08 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:08 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:09 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:10 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:10 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:11 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:11 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:11 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:12 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:13 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:13 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:13 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:14 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:14 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:14 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:15 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:15 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:15 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:16 salon volumio[1371]: Searching plugin music_service/spop Dec 12 22:50:16 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , search Dec 12 22:50:16 salon volumio[1371]: info: All search sources collected, pushing search results Dec 12 22:50:20 salon go-librespot[1710]: time="2025-12-12T22:50:20+01:00" level=trace msg="sent dealer ping" Dec 12 22:50:20 salon go-librespot[1710]: time="2025-12-12T22:50:20+01:00" level=trace msg="received dealer pong" Dec 12 22:50:41 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Dec 12 22:50:41 salon volumio[1371]: info: In handleBrowseUri, curUri=spotify:album:0FRfFn9Hn9BQutqeYHAJdk Dec 12 22:50:41 salon volumio[1371]: info: Preload queue cleared Dec 12 22:50:41 salon volumio[1371]: info: Preloading song: spotify:track:0wwVlguh3Jx4FJi5Q9GC88 Dec 12 22:50:41 salon volumio[1371]: info: Exploding uri spotify:track:0wwVlguh3Jx4FJi5Q9GC88 in service spop Dec 12 22:50:41 salon volumio[1371]: SPOTIFY: EXPLODING URI:spotify:track:0wwVlguh3Jx4FJi5Q9GC88 Dec 12 22:50:42 salon volumio[1371]: info: Executing endpoint getSimilarAlbums Dec 12 22:50:42 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Dec 12 22:50:42 salon volumio[1371]: info: Executing endpoint getSimilarAlbums Dec 12 22:50:42 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarAlbums Dec 12 22:50:42 salon volumio[1371]: info: Executing endpoint metavolumio Dec 12 22:50:42 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 12 22:50:42 salon volumio[1371]: info: Executing endpoint metavolumio Dec 12 22:50:42 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 12 22:50:42 salon volumio[1371]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","service":"spop","name":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","type":"song","duration":194,"albumart":"https://i.scdn.co/image/ab67616d0000b2737de85d1fd0b2d92f83dc3e2b","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Dec 12 22:50:42 salon volumio[1371]: info: Executing endpoint metavolumio Dec 12 22:50:42 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 12 22:50:42 salon volumio[1371]: info: Executing endpoint metavolumio Dec 12 22:50:42 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 12 22:50:48 salon volumio[1371]: info: Preload queue cleared Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::ClearQueue Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::stop Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 22:50:48 salon volumio[1371]: info: CorePlayQueue::clearPlayQueue Dec 12 22:50:48 salon volumio[1371]: info: CorePlayQueue::saveQueue Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::volumioPushQueue Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::addQueueItems Dec 12 22:50:48 salon volumio[1371]: info: CorePlayQueue::addQueueItems Dec 12 22:50:48 salon volumio[1371]: info: Preload queue cleared Dec 12 22:50:48 salon volumio[1371]: info: Adding Item to queue: spotify:album:0FRfFn9Hn9BQutqeYHAJdk Dec 12 22:50:48 salon volumio[1371]: info: Exploding uri spotify:album:0FRfFn9Hn9BQutqeYHAJdk in service spop Dec 12 22:50:48 salon volumio[1371]: SPOTIFY: EXPLODING URI:spotify:album:0FRfFn9Hn9BQutqeYHAJdk Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::volumioPushQueue Dec 12 22:50:48 salon volumio[1371]: info: CorePlayQueue::saveQueue Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::updateTrackBlock Dec 12 22:50:48 salon volumio[1371]: info: CorePlayQueue::getTrackBlock Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:50:48 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::volumioPlay Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::play index 0 Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::stop Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::play index undefined Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 22:50:48 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:48 salon volumio[1371]: info: CoreStateMachine::startPlaybackTimer Dec 12 22:50:48 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::volumioGetVisibleSources Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 22:50:48 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 12 22:50:48 salon volumio[1371]: info: [1765576248700] ControllerSpotify::clearAddPlayTrack Dec 12 22:50:48 salon volumio[1371]: info: Sending Spotify command with payload to local API: /player/play Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="resolved context of track" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="loading track (paused: false, position: 8ms)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=trace msg="emitting websocket event: will_play" Dec 12 22:50:49 salon volumio[1371]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","play_origin":"go-librespot"}} Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="selected format OGG_VORBIS_160 (4cda9193e0b40237096179cad168797c626bb965)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="requested aes key for file 4cda9193e0b40237096179cad168797c626bb965, gid: 0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1654" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="fetched first chunk of 8, total size is 3876549 bytes" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=trace msg="seek to 8ms (diff: -214ms, samples: 352, bytes: 0)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="created new output device" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1270" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="fetched chunk 2/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=info msg="loaded track \"Nobody Told Me (from \\\"Pluribus\\\")\" (paused: false, position: 8ms, duration: 194333ms, prefetched: false)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="fetched chunk 1/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="fetched chunk 3/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=trace msg="scheduling prefetch in 164s" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=trace msg="emitting websocket event: metadata" Dec 12 22:50:49 salon volumio[1371]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","name":"Nobody Told Me (from \"Pluribus\")","artist_names":["Murat Evgin"],"album_name":"Nobody Told Me (from \"Pluribus\")","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","position":8,"duration":194333,"release_date":"year:2025 month:11 day:7","track_number":1,"disc_number":1}} Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:50:49 salon go-librespot[1710]: time="2025-12-12T22:50:49+01:00" level=trace msg="emitting websocket event: playing" Dec 12 22:50:49 salon volumio[1371]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","resume":false,"play_origin":"go-librespot"}} Dec 12 22:50:49 salon volumio[1371]: SPOTIFY: PUSH STATE SPOTIFY Dec 12 22:50:49 salon volumio[1371]: SPOTIFY: {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":8,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:50:49 salon volumio[1371]: info: CoreCommandRouter::servicePushState Dec 12 22:50:49 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:49 salon volumio[1371]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":8,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:50:49 salon volumio[1371]: verbose: CURRENT POSITION 0 Dec 12 22:50:49 salon go-librespot[1710]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Dec 12 22:50:49 salon volumio[1371]: info: CoreStateMachine::syncState stateService play Dec 12 22:50:49 salon volumio[1371]: info: CoreStateMachine::syncState currentStatus stop Dec 12 22:50:49 salon go-librespot[1707]: Aborted Dec 12 22:50:49 salon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Dec 12 22:50:49 salon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 22:50:49 salon volumio[1371]: info: Connection to go-librespot Websocket closed Dec 12 22:50:50 salon systemd[1]: go-librespot-daemon.service: Consumed 1.508s CPU time. Dec 12 22:50:50 salon volumio[1371]: SPOTIFY: PUSH STATE SPOTIFY Dec 12 22:50:50 salon volumio[1371]: SPOTIFY: {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":8,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:50:50 salon volumio[1371]: info: CoreCommandRouter::servicePushState Dec 12 22:50:50 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:50 salon volumio[1371]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":8,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:50:50 salon volumio[1371]: verbose: CURRENT POSITION 0 Dec 12 22:50:50 salon volumio[1371]: info: CoreStateMachine::syncState stateService play Dec 12 22:50:50 salon volumio[1371]: info: CoreStateMachine::syncState currentStatus play Dec 12 22:50:50 salon volumio[1371]: info: Received an update from plugin. extracting info from payload Dec 12 22:50:50 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:50:50 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:50 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 22:50:50 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:50:50 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:50:50 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:50:50 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:50:50 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:50 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:50:50 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:50 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:50:50 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:50:50 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:50:50 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:50:50 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:50:50 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status play Dec 12 22:50:50 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status play Dec 12 22:50:50 salon sudo[5907]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 12 22:50:50 salon sudo[5907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:50:50 salon sudo[5909]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 12 22:50:50 salon sudo[5909]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:50:50 salon systemd[1]: Started peppyspectrum.service - peppyspectrum Daemon. Dec 12 22:50:50 salon sudo[5909]: pam_unix(sudo:session): session closed for user root Dec 12 22:50:50 salon sudo[5907]: pam_unix(sudo:session): session closed for user root Dec 12 22:50:50 salon volumio[1371]: info: peppyspectrum Daemon Started Dec 12 22:50:50 salon volumio[1371]: info: peppyspectrum Daemon Started Dec 12 22:50:52 salon systemd[1]: peppyspectrum.service: Deactivated successfully. Dec 12 22:50:52 salon systemd[1]: peppyspectrum.service: Consumed 1.141s CPU time. Dec 12 22:50:52 salon volumio[1371]: info: Initializing connection to go-librespot Websocket Dec 12 22:50:53 salon volumio[1371]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 22:50:53 salon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 12 22:50:53 salon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 22:50:53 salon systemd[1]: go-librespot-daemon.service: Consumed 1.508s CPU time. Dec 12 22:50:53 salon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 22:50:53 salon go-librespot[5916]: go-librespot daemon starting... Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=debug msg="app state loaded" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=info msg="zeroconf server listening on port 45135" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=debug msg="obtained new client token: AABsmGxmI6pRTPHK0kOiZFqZvYfo0x3JxUOTPewWFWPAdg70bE0p+RIypLsdC9HlwyNPkNFDljFpqbzQmZ+0tOf12hRxc71GJe5oMC/GBgUgH3kWvFQSuVXq2AxVNFoUTvmaAcM8VF8wVEVIU/jl+OwQX/bU5roGKynqaRlgE4djGou8M0/nO9T1OrPoRx9hizW4QkKPpvqq0WdyDr6Qzm3qbG3OkUzZxEQusO4nbKuaJheNof4Sw8ftTcE=" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=debug msg="completed keyexchange" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=debug msg="completed challenge" Dec 12 22:50:53 salon go-librespot[5917]: time="2025-12-12T22:50:53+01:00" level=info msg="authenticated AP" username="th***74" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=info msg="authenticated Login5" username="th***74" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="initializing zeroconf session" username="th***74" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="dealer connection opened" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=trace msg="starting accesspoint recv loop" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=trace msg="starting dealer recv loop" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=trace msg="received accesspoint ping" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="received connection id: ZDVlYmNkOWMtYWVj...QjA5OTkxODY4NQ==" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=trace msg="received accesspoint pong ack" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="update volume requested to 65535/65535" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 12 22:50:54 salon go-librespot[5917]: time="2025-12-12T22:50:54+01:00" level=trace msg="emitting websocket event: volume" Dec 12 22:50:56 salon volumio[1371]: info: Initializing connection to go-librespot Websocket Dec 12 22:50:56 salon go-librespot[5917]: time="2025-12-12T22:50:56+01:00" level=debug msg="new websocket client" Dec 12 22:50:56 salon volumio[1371]: info: Connection to go-librespot Websocket established Dec 12 22:50:59 salon volumio[1371]: info: Getting Spotify volume Dec 12 22:50:59 salon volumio[1371]: info: Spotify volume: 100 Dec 12 22:50:59 salon volumio[1371]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Dec 12 22:50:59 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:50:59 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:15 salon volumio[1371]: info: CoreCommandRouter::volumioSeek Dec 12 22:51:15 salon volumio[1371]: info: CoreStateMachine::seek Dec 12 22:51:15 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:15 salon volumio[1371]: info: TRACKBLOCK {"service":"spop","type":"song","title":"Nobody Told Me (from \"Pluribus\")","name":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d0000b2737de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify","duration":194,"channels":2} Dec 12 22:51:15 salon volumio[1371]: info: CoreStateMachine::startPlaybackTimer Dec 12 22:51:15 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:15 salon volumio[1371]: info: CoreCommandRouter::volumioGetVisibleSources Dec 12 22:51:15 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 22:51:15 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 12 22:51:15 salon volumio[1371]: info: Spotify seek to: 85000 Dec 12 22:51:15 salon volumio[1371]: info: Sending Spotify command with payload to local API: /player/seek Dec 12 22:51:15 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:51:15 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:15 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 22:51:15 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:51:15 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:51:15 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:51:15 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:51:15 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:15 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status play Dec 12 22:51:15 salon sudo[5975]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 12 22:51:15 salon sudo[5975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:51:15 salon systemd[1]: Started peppyspectrum.service - peppyspectrum Daemon. Dec 12 22:51:15 salon sudo[5975]: pam_unix(sudo:session): session closed for user root Dec 12 22:51:15 salon volumio[1371]: info: peppyspectrum Daemon Started Dec 12 22:51:16 salon systemd[1]: peppyspectrum.service: Deactivated successfully. Dec 12 22:51:24 salon go-librespot[5917]: time="2025-12-12T22:51:24+01:00" level=trace msg="sent dealer ping" Dec 12 22:51:24 salon go-librespot[5917]: time="2025-12-12T22:51:24+01:00" level=trace msg="received dealer pong" Dec 12 22:51:25 salon volumio[1371]: info: CoreCommandRouter::volumioNext Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::next Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::stop Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::stPlaybackTimer Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::updateTrackBlock Dec 12 22:51:25 salon volumio[1371]: info: CorePlayQueue::getTrackBlock Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:51:25 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:25 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 22:51:25 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:51:25 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:51:25 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:51:25 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:51:25 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::serviceStop Dec 12 22:51:25 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:25 salon volumio[1371]: info: CoreCommandRouter::serviceStop Dec 12 22:51:25 salon volumio[1371]: info: Spotify Stop Dec 12 22:51:25 salon volumio[1371]: SPOTIFY: SPOTIFY STOP Dec 12 22:51:25 salon volumio[1371]: SPOTIFY: {"status":"play","position":0,"title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d0000b2737de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","codec":"ogg","seek":85000,"duration":194,"samplerate":"160 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":true,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Dec 12 22:51:25 salon volumio[1371]: info: Sending Spotify command to local API: /player/pause Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::play index undefined Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 22:51:25 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::startPlaybackTimer Dec 12 22:51:25 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:25 salon volumio[1371]: info: CoreCommandRouter::volumioGetVisibleSources Dec 12 22:51:25 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 22:51:25 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 12 22:51:25 salon volumio[1371]: info: [1765576285462] ControllerSpotify::clearAddPlayTrack Dec 12 22:51:25 salon volumio[1371]: info: Sending Spotify command with payload to local API: /player/play Dec 12 22:51:25 salon volumio[1371]: info: CoreStateMachine::updateTrackBlock Dec 12 22:51:25 salon volumio[1371]: info: CorePlayQueue::getTrackBlock Dec 12 22:51:25 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status stop Dec 12 22:51:25 salon sudo[5998]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Dec 12 22:51:25 salon sudo[5998]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="resolved context of track" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:25 salon volumio[1371]: info: touch_display: Setting screensaver timeout to 120 seconds. Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=trace msg="emitting websocket event: will_play" Dec 12 22:51:25 salon volumio[1371]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","play_origin":"go-librespot"}} Dec 12 22:51:25 salon sudo[5998]: pam_unix(sudo:session): session closed for user root Dec 12 22:51:25 salon volumio[1371]: info: peppyspectrum Daemon Stop Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="selected format OGG_VORBIS_160 (4cda9193e0b40237096179cad168797c626bb965)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="requested aes key for file 4cda9193e0b40237096179cad168797c626bb965, gid: 0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="fetched first chunk of 8, total size is 3876549 bytes" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="created new output device" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="fetched chunk 2/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 12 22:51:25 salon go-librespot[5917]: time="2025-12-12T22:51:25+01:00" level=info msg="loaded track \"Nobody Told Me (from \\\"Pluribus\\\")\" (paused: false, position: 0ms, duration: 194333ms, prefetched: false)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:26 salon go-librespot[5917]: time="2025-12-12T22:51:26+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:51:26 salon go-librespot[5917]: time="2025-12-12T22:51:26+01:00" level=trace msg="scheduling prefetch in 164s" Dec 12 22:51:26 salon go-librespot[5917]: time="2025-12-12T22:51:26+01:00" level=trace msg="emitting websocket event: metadata" Dec 12 22:51:26 salon volumio[1371]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","name":"Nobody Told Me (from \"Pluribus\")","artist_names":["Murat Evgin"],"album_name":"Nobody Told Me (from \"Pluribus\")","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","position":0,"duration":194333,"release_date":"year:2025 month:11 day:7","track_number":1,"disc_number":1}} Dec 12 22:51:26 salon go-librespot[5917]: time="2025-12-12T22:51:26+01:00" level=debug msg="fetched chunk 3/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:26 salon go-librespot[5917]: time="2025-12-12T22:51:26+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:51:26 salon go-librespot[5917]: time="2025-12-12T22:51:26+01:00" level=trace msg="emitting websocket event: playing" Dec 12 22:51:26 salon volumio[1371]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","resume":false,"play_origin":"go-librespot"}} Dec 12 22:51:26 salon volumio[1371]: SPOTIFY: PUSH STATE SPOTIFY Dec 12 22:51:26 salon volumio[1371]: SPOTIFY: {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:51:26 salon volumio[1371]: info: CoreCommandRouter::servicePushState Dec 12 22:51:26 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:26 salon volumio[1371]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:51:26 salon volumio[1371]: verbose: CURRENT POSITION 0 Dec 12 22:51:26 salon go-librespot[5917]: time="2025-12-12T22:51:26+01:00" level=debug msg="fetched chunk 1/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:26 salon volumio[1371]: info: CoreStateMachine::syncState stateService play Dec 12 22:51:26 salon volumio[1371]: info: CoreStateMachine::syncState currentStatus stop Dec 12 22:51:26 salon go-librespot[5917]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Dec 12 22:51:26 salon go-librespot[5916]: Aborted Dec 12 22:51:26 salon volumio[1371]: info: Connection to go-librespot Websocket closed Dec 12 22:51:26 salon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Dec 12 22:51:26 salon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 22:51:26 salon volumio[1371]: SPOTIFY: PUSH STATE SPOTIFY Dec 12 22:51:26 salon volumio[1371]: SPOTIFY: {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:51:26 salon volumio[1371]: info: CoreCommandRouter::servicePushState Dec 12 22:51:26 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:26 salon volumio[1371]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:51:26 salon volumio[1371]: verbose: CURRENT POSITION 0 Dec 12 22:51:26 salon volumio[1371]: info: CoreStateMachine::syncState stateService play Dec 12 22:51:26 salon volumio[1371]: info: CoreStateMachine::syncState currentStatus play Dec 12 22:51:26 salon volumio[1371]: info: Received an update from plugin. extracting info from payload Dec 12 22:51:26 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:51:26 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:26 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 22:51:26 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:51:26 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:51:26 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:51:26 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:51:26 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:26 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:51:26 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:26 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:51:26 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:51:26 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:51:26 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:51:26 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:26 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status play Dec 12 22:51:26 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status play Dec 12 22:51:26 salon sudo[6019]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 12 22:51:26 salon sudo[6019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:51:26 salon sudo[6021]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 12 22:51:26 salon sudo[6021]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:51:26 salon systemd[1]: Started peppyspectrum.service - peppyspectrum Daemon. Dec 12 22:51:26 salon sudo[6021]: pam_unix(sudo:session): session closed for user root Dec 12 22:51:26 salon sudo[6019]: pam_unix(sudo:session): session closed for user root Dec 12 22:51:26 salon volumio[1371]: info: peppyspectrum Daemon Started Dec 12 22:51:26 salon volumio[1371]: info: peppyspectrum Daemon Started Dec 12 22:51:27 salon systemd[1]: peppyspectrum.service: Deactivated successfully. Dec 12 22:51:29 salon volumio[1371]: info: Initializing connection to go-librespot Websocket Dec 12 22:51:29 salon volumio[1371]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 22:51:29 salon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 12 22:51:29 salon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 22:51:29 salon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 22:51:29 salon go-librespot[6035]: go-librespot daemon starting... Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=debug msg="app state loaded" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=info msg="zeroconf server listening on port 33279" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=debug msg="obtained new client token: AACDpFbdoBieiOkfiCzXXoCS8Th4CewOIHFatFrHz6x2u9zKQYeKHK+AAH9WCoD3kpzVH6+GDqyqiSs4CztzmxXfvlL/sTwhjo+IARCOL8CY84jw7tfNCogozZhoL9HGyhAxT055brQJXdr/3MejqgmUY7U/0OXP8M8IHYYTx2HI/l+X152RaOrdwXAhDlKEzBIp/Nn1oEHtsewQcfnAPZs0nLQMVTdO0IWX4I2/SNOq1FY6Z9ZW8CAcgOw=" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=debug msg="completed keyexchange" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=debug msg="completed challenge" Dec 12 22:51:29 salon go-librespot[6036]: time="2025-12-12T22:51:29+01:00" level=info msg="authenticated AP" username="th***74" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=info msg="authenticated Login5" username="th***74" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="initializing zeroconf session" username="th***74" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="dealer connection opened" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=trace msg="starting accesspoint recv loop" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=trace msg="starting dealer recv loop" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=trace msg="received accesspoint ping" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="received connection id: N2RkMmJhYjAtNjRm...MEQzMTlENUI4NA==" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=trace msg="received accesspoint pong ack" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="update volume requested to 65535/65535" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 12 22:51:30 salon go-librespot[6036]: time="2025-12-12T22:51:30+01:00" level=trace msg="emitting websocket event: volume" Dec 12 22:51:32 salon volumio[1371]: info: Initializing connection to go-librespot Websocket Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="new websocket client" Dec 12 22:51:32 salon volumio[1371]: info: Connection to go-librespot Websocket established Dec 12 22:51:32 salon volumio[1371]: info: CoreCommandRouter::volumioNext Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::next Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::stop Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::stPlaybackTimer Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::updateTrackBlock Dec 12 22:51:32 salon volumio[1371]: info: CorePlayQueue::getTrackBlock Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:51:32 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:32 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 22:51:32 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:51:32 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:51:32 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:51:32 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:51:32 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::serviceStop Dec 12 22:51:32 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:32 salon volumio[1371]: info: CoreCommandRouter::serviceStop Dec 12 22:51:32 salon volumio[1371]: info: Spotify Stop Dec 12 22:51:32 salon volumio[1371]: SPOTIFY: SPOTIFY STOP Dec 12 22:51:32 salon volumio[1371]: SPOTIFY: {"status":"play","position":0,"title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d0000b2737de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","codec":"ogg","seek":0,"duration":194,"samplerate":"160 kbps","bitdepth":"16 bit","channels":2,"random":false,"repeat":true,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":true,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Dec 12 22:51:32 salon volumio[1371]: info: Sending Spotify command to local API: /player/pause Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::play index undefined Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 22:51:32 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::startPlaybackTimer Dec 12 22:51:32 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:32 salon volumio[1371]: info: CoreCommandRouter::volumioGetVisibleSources Dec 12 22:51:32 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 12 22:51:32 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 12 22:51:32 salon volumio[1371]: info: [1765576292497] ControllerSpotify::clearAddPlayTrack Dec 12 22:51:32 salon volumio[1371]: info: Sending Spotify command with payload to local API: /player/play Dec 12 22:51:32 salon volumio[1371]: info: CoreStateMachine::updateTrackBlock Dec 12 22:51:32 salon volumio[1371]: info: CorePlayQueue::getTrackBlock Dec 12 22:51:32 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status stop Dec 12 22:51:32 salon sudo[6046]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Dec 12 22:51:32 salon sudo[6046]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:51:32 salon volumio[1371]: info: touch_display: Setting screensaver timeout to 120 seconds. Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="resolved context of track" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:32 salon sudo[6046]: pam_unix(sudo:session): session closed for user root Dec 12 22:51:32 salon volumio[1371]: info: peppyspectrum Daemon Stop Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=trace msg="emitting websocket event: will_play" Dec 12 22:51:32 salon volumio[1371]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","play_origin":"go-librespot"}} Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="selected format OGG_VORBIS_160 (4cda9193e0b40237096179cad168797c626bb965)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="requested aes key for file 4cda9193e0b40237096179cad168797c626bb965, gid: 0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="fetched first chunk of 8, total size is 3876549 bytes" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="created new output device" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=info msg="loaded track \"Nobody Told Me (from \\\"Pluribus\\\")\" (paused: false, position: 0ms, duration: 194333ms, prefetched: false)" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:32 salon go-librespot[6036]: time="2025-12-12T22:51:32+01:00" level=debug msg="fetched chunk 2/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:33 salon go-librespot[6036]: time="2025-12-12T22:51:33+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:51:33 salon go-librespot[6036]: time="2025-12-12T22:51:33+01:00" level=trace msg="scheduling prefetch in 164s" Dec 12 22:51:33 salon go-librespot[6036]: time="2025-12-12T22:51:33+01:00" level=trace msg="emitting websocket event: metadata" Dec 12 22:51:33 salon volumio[1371]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","name":"Nobody Told Me (from \"Pluribus\")","artist_names":["Murat Evgin"],"album_name":"Nobody Told Me (from \"Pluribus\")","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","position":0,"duration":194333,"release_date":"year:2025 month:11 day:7","track_number":1,"disc_number":1}} Dec 12 22:51:33 salon go-librespot[6036]: time="2025-12-12T22:51:33+01:00" level=debug msg="fetched chunk 3/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:33 salon go-librespot[6036]: time="2025-12-12T22:51:33+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 22:51:33 salon go-librespot[6036]: time="2025-12-12T22:51:33+01:00" level=trace msg="emitting websocket event: playing" Dec 12 22:51:33 salon volumio[1371]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","resume":false,"play_origin":"go-librespot"}} Dec 12 22:51:33 salon volumio[1371]: SPOTIFY: PUSH STATE SPOTIFY Dec 12 22:51:33 salon volumio[1371]: SPOTIFY: {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:51:33 salon volumio[1371]: info: CoreCommandRouter::servicePushState Dec 12 22:51:33 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:33 salon volumio[1371]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:51:33 salon volumio[1371]: verbose: CURRENT POSITION 0 Dec 12 22:51:33 salon volumio[1371]: info: CoreStateMachine::syncState stateService play Dec 12 22:51:33 salon volumio[1371]: info: CoreStateMachine::syncState currentStatus stop Dec 12 22:51:33 salon go-librespot[6036]: time="2025-12-12T22:51:33+01:00" level=debug msg="fetched chunk 1/7, size: 524288" uri="spotify:track:0wwVlguh3Jx4FJi5Q9GC88" Dec 12 22:51:33 salon go-librespot[6036]: go-librespot: pcm_meter.c:1220: snd_pcm_scope_s16_get_channel_buffer: Assertion `s16->buf_areas' failed. Dec 12 22:51:33 salon go-librespot[6035]: Aborted Dec 12 22:51:33 salon volumio[1371]: info: Connection to go-librespot Websocket closed Dec 12 22:51:33 salon systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Dec 12 22:51:33 salon systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 22:51:33 salon volumio[1371]: SPOTIFY: PUSH STATE SPOTIFY Dec 12 22:51:33 salon volumio[1371]: SPOTIFY: {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:51:33 salon volumio[1371]: info: CoreCommandRouter::servicePushState Dec 12 22:51:33 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:33 salon volumio[1371]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Nobody Told Me (from \"Pluribus\")","artist":"Murat Evgin","album":"Nobody Told Me (from \"Pluribus\")","albumart":"https://i.scdn.co/image/ab67616d00001e027de85d1fd0b2d92f83dc3e2b","uri":"spotify:track:0wwVlguh3Jx4FJi5Q9GC88","trackType":"spotify","seek":0,"duration":194,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 22:51:33 salon volumio[1371]: verbose: CURRENT POSITION 0 Dec 12 22:51:33 salon volumio[1371]: info: CoreStateMachine::syncState stateService play Dec 12 22:51:33 salon volumio[1371]: info: CoreStateMachine::syncState currentStatus play Dec 12 22:51:33 salon volumio[1371]: info: Received an update from plugin. extracting info from payload Dec 12 22:51:33 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:51:33 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:33 salon volumio[1371]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 22:51:33 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:51:33 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:51:33 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:51:33 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:51:33 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:33 salon volumio[1371]: info: CoreStateMachine::pushState Dec 12 22:51:33 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:33 salon volumio[1371]: info: CoreCommandRouter::volumioPushState Dec 12 22:51:33 salon volumio[1371]: info: MRS: Pushing multiroomSync output update for this device Dec 12 22:51:33 salon volumio[1371]: info: MRS: Pushing multiroomSync output Dec 12 22:51:33 salon volumio[1371]: info: CoreCommandRouter::volumioGetState Dec 12 22:51:33 salon volumio[1371]: info: CorePlayQueue::getTrack 0 Dec 12 22:51:33 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status play Dec 12 22:51:33 salon volumio[1371]: info: PeppySpectrum ---peppyspectrum status play Dec 12 22:51:33 salon sudo[6052]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 12 22:51:33 salon sudo[6052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:51:33 salon sudo[6054]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppyspectrum.service Dec 12 22:51:33 salon sudo[6054]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 22:51:33 salon systemd[1]: Started peppyspectrum.service - peppyspectrum Daemon. Dec 12 22:51:33 salon sudo[6054]: pam_unix(sudo:session): session closed for user root Dec 12 22:51:33 salon volumio[1371]: info: peppyspectrum Daemon Started Dec 12 22:51:33 salon sudo[6052]: pam_unix(sudo:session): session closed for user root Dec 12 22:51:33 salon volumio[1371]: info: peppyspectrum Daemon Started Dec 12 22:51:34 salon systemd[1]: peppyspectrum.service: Deactivated successfully. Dec 12 22:51:35 salon volumio[1371]: info: Getting Spotify volume Dec 12 22:51:35 salon volumio[1371]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 22:51:35 salon volumio[1371]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 22:51:35 salon volumio[1371]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 12 22:51:35 salon volumio[1371]: errno: -111, Dec 12 22:51:35 salon volumio[1371]: code: 'ECONNREFUSED', Dec 12 22:51:35 salon volumio[1371]: syscall: 'connect', Dec 12 22:51:35 salon volumio[1371]: address: '127.0.0.1', Dec 12 22:51:35 salon volumio[1371]: port: 9879, Dec 12 22:51:35 salon volumio[1371]: response: undefined Dec 12 22:51:35 salon volumio[1371]: } Dec 12 22:51:35 salon volumio[1371]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 22:51:36 salon systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 12 22:51:36 salon systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 22:51:36 salon systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 22:51:36 salon go-librespot[6066]: go-librespot daemon starting... Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=info msg="running go-librespot 0.4.0" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=debug msg="app state loaded" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=info msg="zeroconf server listening on port 44685" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=debug msg="obtained new client token: AAAthatYLfQ88/x7EZuwU0Fy/hjQ7b9vJTEfn8cteLNen5EDPo3kt1LaHGEtJhJHMaHkzm1nwdoX/79jGMCx27mfSpx++VyF3qUVEqRG0VEvXLyp7Fn0cKsqN6jNx+vDipjHbjkoW8ji+eai2Fp6dMPNkcA247mRo2dOfr+AG6zqjrmzbcEvF1AL4uYEN7026cp9HTipYKl/BoZqZ4Tx+xXheTJeami+S1uD1l/CSevTkVL2ZIdE/dpHyR4=" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=debug msg="completed keyexchange" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=debug msg="completed challenge" Dec 12 22:51:36 salon go-librespot[6080]: time="2025-12-12T22:51:36+01:00" level=info msg="authenticated AP" username="th***74" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=info msg="authenticated Login5" username="th***74" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="initializing zeroconf session" username="th***74" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="dealer connection opened" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=trace msg="starting accesspoint recv loop" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=trace msg="starting dealer recv loop" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=trace msg="received accesspoint ping" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="received connection id: ZTQ4NDRiMzEtNGQ2...MkEyN0RBMUNCOA==" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=trace msg="received accesspoint pong ack" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="put connect state because NEW_DEVICE" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="update volume requested to 65535/65535" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Dec 12 22:51:37 salon go-librespot[6080]: time="2025-12-12T22:51:37+01:00" level=trace msg="emitting websocket event: volume" Dec 12 22:51:37 salon sudo[6100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-12 22:50' Dec 12 22:51:37 salon sudo[6100]: 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"