-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Sun 2025-01-12 13:09:12 CET. -- Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=trace msg="emitting websocket event: not_playing" Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3l9zh5c8N7YV340YnRN6So" Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:1m81wPbpnAXEj0J4C270wo","play_origin":"go-librespot"}} Jan 12 13:08:02 volumio volumio[1175]: error: Failed to decode event: not_playing Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=trace msg="emitting websocket event: will_play" Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","play_origin":"go-librespot"}} Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=info msg="loaded track \"Crack Baby Dont Come Back\" (paused: false, position: 0ms, duration: 198202ms, prefetched: true)" uri="spotify:track:3l9zh5c8N7YV340YnRN6So" Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=trace msg="scheduling prefetch in 168s" Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=trace msg="emitting websocket event: metadata" Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","name":"Crack Baby Dont Come Back","artist_names":["Tom Green"],"album_name":"The Tom Green Show","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","position":0,"duration":198202,"release_date":"year:2019 month:5 day:17","track_number":9,"disc_number":1}} Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:08:02 volumio go-librespot[1531]: time="2025-01-12T13:08:02+01:00" level=trace msg="emitting websocket event: playing" Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","play_origin":"go-librespot"}} Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: PUSH STATE SPOTIFY Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: {"status":"play","service":"spop","title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","seek":0,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:08:02 volumio volumio[1175]: info: CoreCommandRouter::servicePushState Jan 12 13:08:02 volumio volumio[1175]: info: CorePlayQueue::getTrack 3 Jan 12 13:08:02 volumio volumio[1175]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","seek":0,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:08:02 volumio volumio[1175]: verbose: CURRENT POSITION 3 Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::syncState stateService play Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::syncState currentStatus play Jan 12 13:08:02 volumio volumio[1175]: info: Received an update from plugin. extracting info from payload Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:08:02 volumio volumio[1175]: info: CorePlayQueue::getTrack 3 Jan 12 13:08:02 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 13:08:02 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:08:02 volumio volumio[1175]: info: CorePlayQueue::getTrack 3 Jan 12 13:08:02 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::startPlaybackTimer Jan 12 13:08:02 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: PUSH STATE SPOTIFY Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: {"status":"play","service":"spop","title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","seek":0,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:08:02 volumio volumio[1175]: info: CoreCommandRouter::servicePushState Jan 12 13:08:02 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:02 volumio volumio[1175]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","seek":0,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:08:02 volumio volumio[1175]: verbose: CURRENT POSITION 4 Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::syncState stateService play Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::syncState currentStatus play Jan 12 13:08:02 volumio volumio[1175]: info: Received an update from plugin. extracting info from payload Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:08:02 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:02 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 13:08:02 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:08:02 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:08:02 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:02 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:08:02 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:08:03 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:08:03 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:03 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 13:08:03 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:08:03 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:08:16 volumio volumio[1175]: info: CoreCommandRouter::volumioPause Jan 12 13:08:16 volumio volumio[1175]: info: CoreStateMachine::pause Jan 12 13:08:16 volumio volumio[1175]: info: CoreStateMachine::stPlaybackTimer Jan 12 13:08:16 volumio volumio[1175]: info: CoreStateMachine::servicePause Jan 12 13:08:16 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:16 volumio volumio[1175]: info: CoreCommandRouter::servicePause Jan 12 13:08:16 volumio volumio[1175]: info: Spotify Received pause Jan 12 13:08:16 volumio volumio[1175]: SPOTIFY: SPOTIFY PAUSE Jan 12 13:08:16 volumio volumio[1175]: SPOTIFY: {"status":"play","position":4,"title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d0000b273ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","codec":"ogg","seek":501,"duration":198,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":38,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jan 12 13:08:16 volumio volumio[1175]: info: Sending Spotify command to local API: /player/pause Jan 12 13:08:16 volumio go-librespot[1531]: time="2025-01-12T13:08:16+01:00" level=debug msg="pause track at 14196ms" Jan 12 13:08:16 volumio go-librespot[1531]: time="2025-01-12T13:08:16+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:08:16 volumio go-librespot[1531]: time="2025-01-12T13:08:16+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:08:16 volumio go-librespot[1531]: time="2025-01-12T13:08:16+01:00" level=trace msg="emitting websocket event: paused" Jan 12 13:08:16 volumio volumio[1175]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","play_origin":"go-librespot"}} Jan 12 13:08:16 volumio volumio[1175]: SPOTIFY: PUSH STATE SPOTIFY Jan 12 13:08:16 volumio volumio[1175]: SPOTIFY: {"status":"pause","service":"spop","title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","seek":14000,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:08:16 volumio volumio[1175]: info: CoreCommandRouter::servicePushState Jan 12 13:08:16 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:16 volumio volumio[1175]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","seek":14000,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:08:16 volumio volumio[1175]: verbose: CURRENT POSITION 4 Jan 12 13:08:16 volumio volumio[1175]: info: CoreStateMachine::syncState stateService pause Jan 12 13:08:16 volumio volumio[1175]: info: CoreStateMachine::syncState currentStatus pause Jan 12 13:08:16 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:08:16 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:16 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 13:08:16 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:08:16 volumio volumio[1175]: info: CoreStateMachine::stPlaybackTimer Jan 12 13:08:16 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:08:16 volumio volumio[1175]: info: touch_display: Setting screensaver timeout to 120 seconds. Jan 12 13:08:35 volumio volumio[1175]: info: Enabling plugin fusiondsp Jan 12 13:08:35 volumio volumio[1175]: info: Loading plugin "fusiondsp"... Jan 12 13:08:35 volumio volumio[1175]: info: Preparing to generate the ALSA configuration file Jan 12 13:08:35 volumio volumio[1175]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Jan 12 13:08:35 volumio volumio[1175]: info: Reading ALSA contributions from plugins. Jan 12 13:08:35 volumio volumio[1175]: info: Asound.conf file written Jan 12 13:08:35 volumio sudo[7104]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Jan 12 13:08:35 volumio sudo[7104]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio sudo[7104]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:35 volumio volumio[1175]: info: Output device has changed, restarting MPD Jan 12 13:08:35 volumio sudo[7110]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 13:08:35 volumio sudo[7110]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio sudo[7110]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:35 volumio volumio[1175]: info: Output device has changed, restarting Shairport Sync Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 13:08:35 volumio sudo[7113]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 13:08:35 volumio sudo[7113]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio systemd[1]: Stopping Music Player Daemon... Jan 12 13:08:35 volumio systemd[1]: mpd.service: Succeeded. Jan 12 13:08:35 volumio systemd[1]: Stopped Music Player Daemon. Jan 12 13:08:35 volumio volumio[1175]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 13:08:35 volumio volumio[1175]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio systemd[1]: Starting Music Player Daemon... Jan 12 13:08:35 volumio volumio[1175]: info: PLUGIN START: fusiondsp Jan 12 13:08:35 volumio volumio[1175]: info: Loading i18n strings for locale de Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: FusionDsp - mixtype--------------------- Hardware Jan 12 13:08:35 volumio volumio[1175]: info: Preparing to generate the ALSA configuration file Jan 12 13:08:35 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Jan 12 13:08:35 volumio sudo[7118]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 13:08:35 volumio sudo[7118]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio volumio[1175]: info: Done. Jan 12 13:08:35 volumio sudo[7118]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:35 volumio volumio[1175]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Jan 12 13:08:35 volumio volumio[1175]: info: Reading ALSA contributions from plugins. Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 12 13:08:35 volumio volumio[1175]: info: MPD Permissions set Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 12 13:08:35 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: Starting Shairport Sync Jan 12 13:08:35 volumio volumio[1175]: info: Asound.conf file unchanged, so no further update is needed Jan 12 13:08:35 volumio volumio[1175]: info: Output device has changed, restarting MPD Jan 12 13:08:35 volumio sudo[7129]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 13:08:35 volumio sudo[7129]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jan 12 13:08:35 volumio systemd[1]: shairport-sync.service: Succeeded. Jan 12 13:08:35 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jan 12 13:08:35 volumio sudo[7132]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 12 13:08:35 volumio sudo[7132]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jan 12 13:08:35 volumio volumio[1175]: info: Output device has changed, restarting Shairport Sync Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 13:08:35 volumio sudo[7132]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:35 volumio sudo[7137]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 12 13:08:35 volumio sudo[7137]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio sudo[7129]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:35 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Jan 12 13:08:35 volumio systemd[1]: mpd.service: Succeeded. Jan 12 13:08:35 volumio systemd[1]: Stopped Music Player Daemon. Jan 12 13:08:35 volumio systemd[1]: Starting Music Player Daemon... Jan 12 13:08:35 volumio volumio[1175]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 12 13:08:35 volumio volumio[1175]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jan 12 13:08:35 volumio sudo[7145]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jan 12 13:08:35 volumio sudo[7145]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 12 13:08:35 volumio volumio[1175]: info: MPD Permissions set Jan 12 13:08:35 volumio volumio[1175]: info: Shairport-Sync Started Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio sudo[7145]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:35 volumio volumio[1175]: info: Starting Shairport Sync Jan 12 13:08:35 volumio sudo[7155]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 12 13:08:35 volumio sudo[7155]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:35 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jan 12 13:08:35 volumio systemd[1]: shairport-sync.service: Succeeded. Jan 12 13:08:35 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: running Jan 12 13:08:35 volumio volumio[1175]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jan 12 13:08:35 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jan 12 13:08:35 volumio sudo[7155]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:35 volumio volumio[1175]: info: Shairport-Sync Started Jan 12 13:08:36 volumio mpd[7149]: Jan 12 13:08 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 12 13:08:36 volumio systemd[1]: Started Music Player Daemon. Jan 12 13:08:36 volumio sudo[7113]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:36 volumio sudo[7137]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:36 volumio volumio[1175]: error: MPD error: The expression evaluated to a falsy value: Jan 12 13:08:36 volumio volumio[1175]: assert.ok(self.idling) Jan 12 13:08:36 volumio volumio[1175]: error: The expression evaluated to a falsy value: Jan 12 13:08:36 volumio volumio[1175]: assert.ok(self.idling) Jan 12 13:08:36 volumio volumio[1175]: error: updateQueue error: null Jan 12 13:08:37 volumio volumio[1175]: info: camilladsp spawned new process with pid 7168, instance 1, run: true Jan 12 13:08:37 volumio volumio[1175]: info: camilladsp service started and running in background, instance 1 Jan 12 13:08:37 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 12 13:08:37 volumio volumio[1175]: info: FusionDsp - AAAAAAAAAAAAAA-> 22050 44100 48000 88200 96000 176400 192000 384000 <-AAAAAAAAAAAAA Jan 12 13:08:37 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Jan 12 13:08:37 volumio volumio[1175]: info: FusionDsp loaded Jan 12 13:08:37 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 12 13:08:37 volumio sudo[7174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Jan 12 13:08:37 volumio sudo[7174]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 12 13:08:37 volumio volumio[1175]: info: FusionDsp - Reporting Fusion DSP Enabled Jan 12 13:08:37 volumio volumio[1175]: info: Adding Signal Path Element [object Object] Jan 12 13:08:37 volumio volumio[1175]: info: Adding fusiondspeq DSP Signal Path Element Jan 12 13:08:37 volumio volumio[1175]: info: FusionDsp - ---- installed callbackRead Jan 12 13:08:37 volumio volumio[1175]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jan 12 13:08:37 volumio volumio[1175]: error: FusionDsp - WebSocket error: [object Object] Jan 12 13:08:37 volumio volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Jan 12 13:08:37 volumio systemd[1]: Started FusionDsp Daemon. Jan 12 13:08:37 volumio sudo[7174]: pam_unix(sudo:session): session closed for user root Jan 12 13:08:38 volumio volumio[1175]: 0+0 records in Jan 12 13:08:38 volumio volumio[1175]: 0+0 records out Jan 12 13:08:38 volumio volumio[1175]: 0 bytes copied, 5.0148e-05 s, 0.0 kB/s Jan 12 13:08:38 volumio volumio[1175]: info: camilladsp spawned new process with pid 7179, instance 1, run: true Jan 12 13:08:38 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Jan 12 13:08:39 volumio volumio[1175]: info: Enabling plugin ampswitch Jan 12 13:08:39 volumio volumio[1175]: info: Loading plugin "ampswitch"... Jan 12 13:08:40 volumio volumio[1175]: info: PLUGIN START: ampswitch Jan 12 13:08:40 volumio volumio[1175]: info: Done. Jan 12 13:08:40 volumio volumio[1175]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jan 12 13:08:40 volumio volumio[1175]: info: CoreCommandRouter::volumioGetState Jan 12 13:08:40 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] CurState: pause PrevState: na Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] CurState: pause PrevState: na Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] Togle GPIO: OFF Jan 12 13:08:40 volumio volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] Setting UI defaults Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] Port: 24 Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] Inverted: false Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] Latched: false Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] On pulse width: 500 Jan 12 13:08:40 volumio volumio[1175]: info: [ASDebug] Off pulse width: 500 Jan 12 13:08:43 volumio volumio[1175]: Searching plugin music_service/spop Jan 12 13:08:43 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:08:44 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:08:44 volumio volumio[1175]: Searching plugin music_service/spop Jan 12 13:08:44 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:08:44 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:08:46 volumio volumio[1175]: Searching plugin music_service/spop Jan 12 13:08:46 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:08:47 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:08:47 volumio volumio[1175]: Searching plugin music_service/spop Jan 12 13:08:47 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:08:48 volumio volumio[1175]: Searching plugin music_service/spop Jan 12 13:08:48 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:08:48 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:08:48 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:08:49 volumio volumio[1175]: Searching plugin music_service/spop Jan 12 13:08:49 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:08:49 volumio volumio[1175]: Searching plugin music_service/spop Jan 12 13:08:49 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:08:50 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:08:50 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:08:52 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 12 13:08:52 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 12 13:08:53 volumio volumio[1175]: error: Failed to check for new versions for plugin YouTube Music: Error: Invalid argument not valid semver ('' received) Jan 12 13:08:54 volumio volumio[1175]: Searching plugin music_service/spop Jan 12 13:08:54 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:08:55 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:08:55 volumio volumio[1175]: info: [ASDebug] Port: 24 Jan 12 13:08:55 volumio volumio[1175]: info: [ASDebug] Inverted: false Jan 12 13:08:55 volumio volumio[1175]: info: [ASDebug] Delay: 720 Jan 12 13:08:58 volumio volumio[1175]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 12 13:09:02 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jan 12 13:09:02 volumio volumio[1175]: info: In handleBrowseUri, curUri=spotify:artist:0hLd40hVpRDGENe4KGZLnW Jan 12 13:09:03 volumio volumio[1175]: info: Preload queue cleared Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:0DfG1ltJnZyq4Tx3ZLL7ZU Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:6vgnumRgsZcc5fVFtpIRO1 Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:3TBRJsLCcwroEkA3tD4u2N Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:6a0lr0jt8lKDJhsAYA49NS Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:3HMnzW11ZTELitvvX13yLb Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:6tetorrFfVEwugqcgfwEm1 Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:5VcHptWy0oSCisPLod31rs Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:44jfDGRpP9KtZCe5jf6De6 Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:3oI0u1hCFjlfPqlqauNMOW Jan 12 13:09:03 volumio volumio[1175]: info: Preloading song: spotify:track:4oK7oq9OwIcDwYadhxpViQ Jan 12 13:09:03 volumio volumio[1175]: info: Preload queue cleared Jan 12 13:09:03 volumio volumio[1175]: info: Executing endpoint getSimilarArtists Jan 12 13:09:03 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Jan 12 13:09:03 volumio volumio[1175]: info: Executing endpoint getSimilarArtists Jan 12 13:09:03 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Jan 12 13:09:03 volumio volumio[1175]: info: Executing endpoint getSimilarArtists Jan 12 13:09:03 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Jan 12 13:09:03 volumio volumio[1175]: info: Executing endpoint getSimilarArtists Jan 12 13:09:03 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getSimilarArtists Jan 12 13:09:03 volumio volumio[1175]: info: Executing endpoint metavolumio Jan 12 13:09:03 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jan 12 13:09:03 volumio volumio[1175]: info: Executing endpoint metavolumio Jan 12 13:09:03 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jan 12 13:09:04 volumio volumio[1175]: info: Executing endpoint metavolumio Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_music , getSuperSearchEnabledSourcesList Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::volumioGetBrowseSources Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: youtube2 , search Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jan 12 13:09:04 volumio volumio[1175]: info: [ytmusic] InnertubeLoader: creating Innertube instance... Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: 80s80s , search Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: podcast , search Jan 12 13:09:04 volumio volumio[1175]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin podcast Jan 12 13:09:04 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , search Jan 12 13:09:05 volumio volumio[1175]: info: Executing endpoint metavolumio Jan 12 13:09:05 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Jan 12 13:09:07 volumio volumio[1175]: info: [ytmusic] InnertubeLoader: obtaining po_token by visitorData... Jan 12 13:09:08 volumio volumio[1175]: [YOUTUBEJS][Text]: Unable to find matching run for command run. Skipping... { Jan 12 13:09:08 volumio volumio[1175]: command_run: { startIndex: 0, length: 64, onTap: { innertubeCommand: [Object] } }, Jan 12 13:09:08 volumio volumio[1175]: input_data: { Jan 12 13:09:08 volumio volumio[1175]: content: 'NENA | 99 Luftballons [1983] [Offizielles HD Musikvideo] · 3:55', Jan 12 13:09:08 volumio volumio[1175]: commandRuns: [ [Object] ] Jan 12 13:09:08 volumio volumio[1175]: }, Jan 12 13:09:08 volumio volumio[1175]: parsed_runs: [ Jan 12 13:09:08 volumio volumio[1175]: { Jan 12 13:09:08 volumio volumio[1175]: text: 'NENA | 99 Luftballons [1983] [Offizielles HD Musikvideo] · 3:55', Jan 12 13:09:08 volumio volumio[1175]: startIndex: 0 Jan 12 13:09:08 volumio volumio[1175]: } Jan 12 13:09:08 volumio volumio[1175]: ] Jan 12 13:09:08 volumio volumio[1175]: } Jan 12 13:09:08 volumio volumio[1175]: [YOUTUBEJS][Text]: Unable to find matching run for command run. Skipping... { Jan 12 13:09:08 volumio volumio[1175]: command_run: { startIndex: 0, length: 61, onTap: { innertubeCommand: [Object] } }, Jan 12 13:09:08 volumio volumio[1175]: input_data: { Jan 12 13:09:08 volumio volumio[1175]: content: 'a-ha - Take On Me (Official Video) [Remastered in 4K] · 4:04', Jan 12 13:09:08 volumio volumio[1175]: commandRuns: [ [Object] ] Jan 12 13:09:08 volumio volumio[1175]: }, Jan 12 13:09:08 volumio volumio[1175]: parsed_runs: [ Jan 12 13:09:08 volumio volumio[1175]: { Jan 12 13:09:08 volumio volumio[1175]: text: 'a-ha - Take On Me (Official Video) [Remastered in 4K] · 4:04', Jan 12 13:09:08 volumio volumio[1175]: startIndex: 0 Jan 12 13:09:08 volumio volumio[1175]: } Jan 12 13:09:08 volumio volumio[1175]: ] Jan 12 13:09:08 volumio volumio[1175]: } Jan 12 13:09:08 volumio volumio[1175]: [YOUTUBEJS][Text]: Unable to find matching run for command run. Skipping... { Jan 12 13:09:08 volumio volumio[1175]: command_run: { startIndex: 0, length: 64, onTap: { innertubeCommand: [Object] } }, Jan 12 13:09:08 volumio volumio[1175]: input_data: { Jan 12 13:09:08 volumio volumio[1175]: content: 'NENA | 99 Luftballons [1983] [Offizielles HD Musikvideo] · 3:55', Jan 12 13:09:08 volumio volumio[1175]: commandRuns: [ [Object] ] Jan 12 13:09:08 volumio volumio[1175]: }, Jan 12 13:09:08 volumio volumio[1175]: parsed_runs: [ Jan 12 13:09:08 volumio volumio[1175]: { Jan 12 13:09:08 volumio volumio[1175]: text: 'NENA | 99 Luftballons [1983] [Offizielles HD Musikvideo] · 3:55', Jan 12 13:09:08 volumio volumio[1175]: startIndex: 0 Jan 12 13:09:08 volumio volumio[1175]: } Jan 12 13:09:08 volumio volumio[1175]: ] Jan 12 13:09:08 volumio volumio[1175]: } Jan 12 13:09:08 volumio volumio[1175]: [YOUTUBEJS][Text]: Unable to find matching run for command run. Skipping... { Jan 12 13:09:08 volumio volumio[1175]: command_run: { startIndex: 0, length: 85, onTap: { innertubeCommand: [Object] } }, Jan 12 13:09:08 volumio volumio[1175]: input_data: { Jan 12 13:09:08 volumio volumio[1175]: content: 'NENA | Irgendwie · Irgendwo · Irgendwann [1984] [Offizielles HD Musikvideo] · 4:17', Jan 12 13:09:08 volumio volumio[1175]: commandRuns: [ [Object] ] Jan 12 13:09:08 volumio volumio[1175]: }, Jan 12 13:09:08 volumio volumio[1175]: parsed_runs: [ Jan 12 13:09:08 volumio volumio[1175]: { Jan 12 13:09:08 volumio volumio[1175]: text: 'NENA | Irgendwie · Irgendwo · Irgendwann [1984] [Offizielles HD Musikvideo] · 4:17', Jan 12 13:09:08 volumio volumio[1175]: startIndex: 0 Jan 12 13:09:08 volumio volumio[1175]: } Jan 12 13:09:08 volumio volumio[1175]: ] Jan 12 13:09:08 volumio volumio[1175]: } Jan 12 13:09:08 volumio volumio[1175]: info: [ytmusic] InnertubeLoader: obtained po_token (expires in 43200 seconds) Jan 12 13:09:08 volumio volumio[1175]: info: [ytmusic] InnertubeLoader: re-create Innertube instance with po_token Jan 12 13:09:08 volumio volumio[1175]: info: [ytmusic] InnertubeLoader: creating Innertube instance with po_token... Jan 12 13:09:10 volumio volumio[1175]: info: [ytmusic] InnertubeLoader: going to refresh po_token in 43100 seconds Jan 12 13:09:10 volumio volumio[1175]: info: Preload queue cleared Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::ClearQueue Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::stop Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::updateTrackBlock Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::getTrackBlock Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::stPlaybackTimer Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::serviceStop Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::serviceStop Jan 12 13:09:10 volumio volumio[1175]: info: Spotify Stop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: SPOTIFY STOP Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: {"status":"pause","position":4,"title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d0000b273ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","codec":"ogg","seek":13767,"duration":198,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":38,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Jan 12 13:09:10 volumio volumio[1175]: info: Sending Spotify command to local API: /player/pause Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::clearPlayQueue Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::saveQueue Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::volumioPushQueue Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::addQueueItems Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::addQueueItems Jan 12 13:09:10 volumio volumio[1175]: info: Preload queue cleared Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:0DfG1ltJnZyq4Tx3ZLL7ZU Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:0DfG1ltJnZyq4Tx3ZLL7ZU in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:0DfG1ltJnZyq4Tx3ZLL7ZU Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:6vgnumRgsZcc5fVFtpIRO1 Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:6vgnumRgsZcc5fVFtpIRO1 in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:6vgnumRgsZcc5fVFtpIRO1 Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:09:10 volumio go-librespot[1531]: time="2025-01-12T13:09:10+01:00" level=debug msg="pause track at 14830ms" Jan 12 13:09:10 volumio volumio[1175]: info: [ASDebug] CurState: stop PrevState: pause Jan 12 13:09:10 volumio go-librespot[1531]: time="2025-01-12T13:09:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0DfG1ltJnZyq4Tx3ZLL7ZU","service":"spop","name":"Rock Me Amadeus","artist":"Falco","album":"Falco 3","type":"song","duration":202,"albumart":"https://i.scdn.co/image/ab67616d0000b27387e51905aaafd4b2e46e9121","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:10 volumio go-librespot[1531]: time="2025-01-12T13:09:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:09:10 volumio go-librespot[1531]: time="2025-01-12T13:09:10+01:00" level=trace msg="emitting websocket event: paused" Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","play_origin":"go-librespot"}} Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: PUSH STATE SPOTIFY Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: {"status":"pause","service":"spop","title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","seek":14000,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::servicePushState Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:09:10 volumio volumio[1175]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Crack Baby Dont Come Back","artist":"Tom Green","album":"The Tom Green Show","albumart":"https://i.scdn.co/image/ab67616d00001e02ba795b9875253935dd3a4319","uri":"spotify:track:3l9zh5c8N7YV340YnRN6So","trackType":"spotify","seek":14000,"duration":198,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:09:10 volumio volumio[1175]: verbose: CURRENT POSITION 4 Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::syncState stateService pause Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::syncState currentStatus stop Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::getTrack 4 Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:09:10 volumio volumio[1175]: info: [ASDebug] CurState: stop PrevState: pause Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6vgnumRgsZcc5fVFtpIRO1","service":"spop","name":"Out Of The Dark","artist":"Falco","album":"Out Of The Dark (Into The Light)","type":"song","duration":217,"albumart":"https://i.scdn.co/image/ab67616d0000b2731a78668fa55a9a8cdeb22a5e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::volumioPushQueue Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::saveQueue Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::updateTrackBlock Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::getTrackBlock Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::volumioPlay Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::play index 1 Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::addQueueItems Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::addQueueItems Jan 12 13:09:10 volumio volumio[1175]: info: Preload queue cleared Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:3TBRJsLCcwroEkA3tD4u2N Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:3TBRJsLCcwroEkA3tD4u2N in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:3TBRJsLCcwroEkA3tD4u2N Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:6a0lr0jt8lKDJhsAYA49NS Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:6a0lr0jt8lKDJhsAYA49NS in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:6a0lr0jt8lKDJhsAYA49NS Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:3HMnzW11ZTELitvvX13yLb Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:3HMnzW11ZTELitvvX13yLb in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:3HMnzW11ZTELitvvX13yLb Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:6tetorrFfVEwugqcgfwEm1 Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:6tetorrFfVEwugqcgfwEm1 in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:6tetorrFfVEwugqcgfwEm1 Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:5VcHptWy0oSCisPLod31rs Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:5VcHptWy0oSCisPLod31rs in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:5VcHptWy0oSCisPLod31rs Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:44jfDGRpP9KtZCe5jf6De6 Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:44jfDGRpP9KtZCe5jf6De6 in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:44jfDGRpP9KtZCe5jf6De6 Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:3oI0u1hCFjlfPqlqauNMOW Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:3oI0u1hCFjlfPqlqauNMOW in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:3oI0u1hCFjlfPqlqauNMOW Jan 12 13:09:10 volumio volumio[1175]: info: Adding Item to queue: spotify:track:4oK7oq9OwIcDwYadhxpViQ Jan 12 13:09:10 volumio volumio[1175]: info: Exploding uri spotify:track:4oK7oq9OwIcDwYadhxpViQ in service spop Jan 12 13:09:10 volumio volumio[1175]: SPOTIFY: EXPLODING URI:spotify:track:4oK7oq9OwIcDwYadhxpViQ Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::stop Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::play index undefined Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::getTrack 1 Jan 12 13:09:10 volumio volumio[1175]: info: CoreStateMachine::startPlaybackTimer Jan 12 13:09:10 volumio volumio[1175]: info: CorePlayQueue::getTrack 1 Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::volumioGetVisibleSources Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 12 13:09:10 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jan 12 13:09:10 volumio volumio[1175]: info: [1736683750925] ControllerSpotify::clearAddPlayTrack Jan 12 13:09:10 volumio volumio[1175]: info: Sending Spotify command with payload to local API: /player/play Jan 12 13:09:10 volumio go-librespot[1531]: time="2025-01-12T13:09:10+01:00" level=debug msg="resolved context of track" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:10 volumio go-librespot[1531]: time="2025-01-12T13:09:10+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:10 volumio go-librespot[1531]: time="2025-01-12T13:09:10+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3TBRJsLCcwroEkA3tD4u2N","service":"spop","name":"Der Kommissar","artist":"Falco","album":"Einzelhaft","type":"song","duration":232,"albumart":"https://i.scdn.co/image/ab67616d0000b27349512287075ab421f6d4a61a","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=trace msg="emitting websocket event: will_play" Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6vgnumRgsZcc5fVFtpIRO1","play_origin":"go-librespot"}} Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6tetorrFfVEwugqcgfwEm1","service":"spop","name":"Vienna Calling","artist":"Falco","album":"Falco 3","type":"song","duration":250,"albumart":"https://i.scdn.co/image/ab67616d0000b27387e51905aaafd4b2e46e9121","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3HMnzW11ZTELitvvX13yLb","service":"spop","name":"Egoist","artist":"Falco","album":"Out Of The Dark (Into The Light)","type":"song","duration":207,"albumart":"https://i.scdn.co/image/ab67616d0000b2731a78668fa55a9a8cdeb22a5e","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5VcHptWy0oSCisPLod31rs","service":"spop","name":"Junge Roemer","artist":"Falco","album":"Junge Roemer - Helnwein Edition","type":"song","duration":270,"albumart":"https://i.scdn.co/image/ab67616d0000b27321354b1f20584db983a78176","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4oK7oq9OwIcDwYadhxpViQ","service":"spop","name":"Ganz Wien","artist":"Drahdiwaberl","album":"Psychoterror","type":"song","duration":308,"albumart":"https://i.scdn.co/image/ab67616d0000b273fa95c27b13e5481107748337","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="selected format OGG_VORBIS_320 (0c903016906ae738dd5b97a2a5658910aec00b3e)" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="requested aes key for file 0c903016906ae738dd5b97a2a5658910aec00b3e, gid: 6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio volumio[1175]: info: All search sources collected, pushing search results Jan 12 13:09:11 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jan 12 13:09:11 volumio volumio[1175]: info: In handleBrowseUri, curUri=spotify:artist:6Tz0QRoe083BcOo2YbG9lV Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:44jfDGRpP9KtZCe5jf6De6","service":"spop","name":"Coming Home - Jeanny, Pt. 2, Ein Jahr danach","artist":"Falco","album":"Emotional (New)","type":"song","duration":332,"albumart":"https://i.scdn.co/image/ab67616d0000b273184c47cac38650ddee021908","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:6a0lr0jt8lKDJhsAYA49NS","service":"spop","name":"Jeanny","artist":"Falco","album":"Falco 3","type":"song","duration":355,"albumart":"https://i.scdn.co/image/ab67616d0000b27387e51905aaafd4b2e46e9121","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3oI0u1hCFjlfPqlqauNMOW","service":"spop","name":"Rock Me Amadeus - 12\" American Edit","artist":"Falco","album":"Falco - The Box","type":"song","duration":351,"albumart":"https://i.scdn.co/image/ab67616d0000b2739b3a730efcb23e33effc7f0d","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jan 12 13:09:11 volumio volumio[1175]: info: CoreCommandRouter::volumioPushQueue Jan 12 13:09:11 volumio volumio[1175]: info: CorePlayQueue::saveQueue Jan 12 13:09:11 volumio volumio[1175]: info: CoreStateMachine::updateTrackBlock Jan 12 13:09:11 volumio volumio[1175]: info: CorePlayQueue::getTrackBlock Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="fetched first chunk of 17, total size is 8823808 bytes" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=info msg="loaded track \"Out Of The Dark\" (paused: false, position: 0ms, duration: 217066ms, prefetched: false)" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=trace msg="scheduling prefetch in 187s" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=trace msg="emitting websocket event: metadata" Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6vgnumRgsZcc5fVFtpIRO1","name":"Out Of The Dark","artist_names":["Falco"],"album_name":"Out Of The Dark (Into The Light)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021a78668fa55a9a8cdeb22a5e","position":0,"duration":217066,"release_date":"year:1998 month:2 day:27","track_number":2,"disc_number":1}} Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=trace msg="emitting websocket event: playing" Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6vgnumRgsZcc5fVFtpIRO1","play_origin":"go-librespot"}} Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: PUSH STATE SPOTIFY Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: {"status":"play","service":"spop","title":"Out Of The Dark","artist":"Falco","album":"Out Of The Dark (Into The Light)","albumart":"https://i.scdn.co/image/ab67616d00001e021a78668fa55a9a8cdeb22a5e","uri":"spotify:track:6vgnumRgsZcc5fVFtpIRO1","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:09:11 volumio volumio[1175]: info: CoreCommandRouter::servicePushState Jan 12 13:09:11 volumio volumio[1175]: info: CorePlayQueue::getTrack 1 Jan 12 13:09:11 volumio volumio[1175]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Out Of The Dark","artist":"Falco","album":"Out Of The Dark (Into The Light)","albumart":"https://i.scdn.co/image/ab67616d00001e021a78668fa55a9a8cdeb22a5e","uri":"spotify:track:6vgnumRgsZcc5fVFtpIRO1","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:09:11 volumio volumio[1175]: verbose: CURRENT POSITION 1 Jan 12 13:09:11 volumio volumio[1175]: info: CoreStateMachine::syncState stateService play Jan 12 13:09:11 volumio volumio[1175]: info: CoreStateMachine::syncState currentStatus stop Jan 12 13:09:11 volumio go-librespot[1531]: time="2025-01-12T13:09:11+01:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:6vgnumRgsZcc5fVFtpIRO1" Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: PUSH STATE SPOTIFY Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: {"status":"play","service":"spop","title":"Out Of The Dark","artist":"Falco","album":"Out Of The Dark (Into The Light)","albumart":"https://i.scdn.co/image/ab67616d00001e021a78668fa55a9a8cdeb22a5e","uri":"spotify:track:6vgnumRgsZcc5fVFtpIRO1","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:09:11 volumio volumio[1175]: info: CoreCommandRouter::servicePushState Jan 12 13:09:11 volumio volumio[1175]: info: CorePlayQueue::getTrack 1 Jan 12 13:09:11 volumio volumio[1175]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Out Of The Dark","artist":"Falco","album":"Out Of The Dark (Into The Light)","albumart":"https://i.scdn.co/image/ab67616d00001e021a78668fa55a9a8cdeb22a5e","uri":"spotify:track:6vgnumRgsZcc5fVFtpIRO1","trackType":"spotify","seek":0,"duration":217,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jan 12 13:09:11 volumio volumio[1175]: verbose: CURRENT POSITION 1 Jan 12 13:09:11 volumio volumio[1175]: info: CoreStateMachine::syncState stateService play Jan 12 13:09:11 volumio volumio[1175]: info: CoreStateMachine::syncState currentStatus play Jan 12 13:09:11 volumio volumio[1175]: info: Received an update from plugin. extracting info from payload Jan 12 13:09:11 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:09:11 volumio volumio[1175]: info: CorePlayQueue::getTrack 1 Jan 12 13:09:11 volumio volumio[1175]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 12 13:09:11 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:09:11 volumio volumio[1175]: info: CoreStateMachine::pushState Jan 12 13:09:11 volumio volumio[1175]: info: CorePlayQueue::getTrack 1 Jan 12 13:09:11 volumio volumio[1175]: info: CoreCommandRouter::volumioPushState Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:09:11 volumio volumio[1175]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Jan 12 13:09:11 volumio volumio[1175]: info: Preload queue cleared Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:2IJftBfq7pJ43tfnOR0RB3 Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:2KTxKoM4iUYCtuUGGIh9Qu Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:0ukySDr4uEzZE36s7t7X8E Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:0xTsllHxzqwYrsPUcruf72 Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:4s5c5vqVno63R0QvWCiDMN Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:0aEgfx6Ar5IZG6TrWeGH0Q Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:44fNhBfmBUhaByY0651VIc Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:5PfiBaZ2e21dKtWclGRYOy Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:2EQ4UPw39W0hbLZ6eeTsr4 Jan 12 13:09:11 volumio volumio[1175]: info: Preloading song: spotify:track:2DDEQ1H1SMTth2gwqIy5Eg Jan 12 13:09:11 volumio volumio[1175]: info: Preload queue cleared Jan 12 13:09:11 volumio volumio[1175]: info: Preload queue cleared Jan 12 13:09:11 volumio volumio[1175]: info: [ASDebug] CurState: play PrevState: pause Jan 12 13:09:11 volumio volumio[1175]: info: [ASDebug] Togle GPIO: ON Jan 12 13:09:11 volumio volumio[1175]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 13:09:11 volumio volumio[1175]: Error: EBADF: bad file descriptor, write Jan 12 13:09:11 volumio volumio[1175]: at Object.writeSync (fs.js:711:3) Jan 12 13:09:11 volumio volumio[1175]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8) Jan 12 13:09:11 volumio volumio[1175]: at AmpSwitchController.on (/data/plugins/system_controller/ampswitch/index.js:207:23) Jan 12 13:09:11 volumio volumio[1175]: at AmpSwitchController.parseStatus (/data/plugins/system_controller/ampswitch/index.js:190:86) Jan 12 13:09:11 volumio volumio[1175]: at Socket.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Jan 12 13:09:11 volumio volumio[1175]: at Socket.onevent (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/socket.js:278:10) Jan 12 13:09:11 volumio volumio[1175]: at Socket.onpacket (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/socket.js:236:12) Jan 12 13:09:11 volumio volumio[1175]: at Manager. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Jan 12 13:09:11 volumio volumio[1175]: at Manager.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Jan 12 13:09:11 volumio volumio[1175]: at Manager.ondecoded (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/manager.js:349:8) Jan 12 13:09:11 volumio volumio[1175]: at Decoder. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Jan 12 13:09:11 volumio volumio[1175]: at Decoder.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Jan 12 13:09:11 volumio volumio[1175]: at Decoder.add (/data/plugins/system_controller/ampswitch/node_modules/socket.io-parser/index.js:254:12) Jan 12 13:09:11 volumio volumio[1175]: at Manager.ondata (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/manager.js:339:16) Jan 12 13:09:11 volumio volumio[1175]: at Socket. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Jan 12 13:09:11 volumio volumio[1175]: at Socket.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) { Jan 12 13:09:11 volumio volumio[1175]: errno: -9, Jan 12 13:09:11 volumio volumio[1175]: syscall: 'write', Jan 12 13:09:11 volumio volumio[1175]: code: 'EBADF' Jan 12 13:09:11 volumio volumio[1175]: } Jan 12 13:09:11 volumio volumio[1175]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 12 13:09:12 volumio sudo[7276]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-12 13:08 Jan 12 13:09:12 volumio sudo[7276]: 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"