Dec 12 16:43:01 volumio kernel: input: SoundCore 2 (AVRCP) as /devices/virtual/input/input0 Dec 12 16:43:01 volumio systemd[1]: Stopping triggerhappy.service - triggerhappy global hotkey daemon... Dec 12 16:43:01 volumio systemd[1]: triggerhappy.service: Deactivated successfully. Dec 12 16:43:01 volumio systemd[1]: Stopped triggerhappy.service - triggerhappy global hotkey daemon. Dec 12 16:43:01 volumio systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... Dec 12 16:43:01 volumio thd[5292]: Unable to parse trigger line: Dec 12 16:43:01 volumio thd[5292]: Unable to parse trigger line: Dec 12 16:43:01 volumio systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. Dec 12 16:43:01 volumio systemd-logind[690]: Watching system buttons on /dev/input/event0 (SoundCore 2 (AVRCP)) Dec 12 16:43:01 volumio bluealsa[899]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Volume Dec 12 16:43:01 volumio bluealsa[899]: bluez.c:1498: Skipping A2DP volume update: 40 Dec 12 16:43:09 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_54_58_41_7A_D8_5E, ...) Dec 12 16:43:13 volumio bluetoothd[681]: Adv Monitor app :1.25 disconnected from D-Bus Dec 12 16:43:20 volumio volumio[1183]: info: CoreCommandRouter::volumioPlay Dec 12 16:43:20 volumio volumio[1183]: info: CoreStateMachine::play index undefined Dec 12 16:43:20 volumio volumio[1183]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 16:43:20 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:43:20 volumio volumio[1183]: info: CoreStateMachine::startPlaybackTimer Dec 12 16:43:20 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:43:20 volumio volumio[1183]: info: [1765554200618] ControllerSpotify::clearAddPlayTrack Dec 12 16:43:20 volumio volumio[1183]: info: Sending Spotify command with payload to local API: /player/play Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=debug msg="resolved context of track" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=trace msg="emitting websocket event: will_play" Dec 12 16:43:20 volumio volumio[1183]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","play_origin":"go-librespot"}} Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1384" Dec 12 16:43:20 volumio go-librespot[1615]: time="2025-12-12T16:43:20+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="selected format OGG_VORBIS_320 (bed90472ee8f7beba18b5dbe9817260f2c6d7334)" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="requested aes key for file bed90472ee8f7beba18b5dbe9817260f2c6d7334, gid: 6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1136" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="fetched first chunk of 18, total size is 9088860 bytes" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="created new output device" Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:1538: Getting BlueALSA PCM: PLAYBACK 08:EB:ED:25:4F:D6 a2dp Dec 12 16:43:21 volumio bluealsa[899]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.GetCodecs() on /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:1296: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Setting constraints Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:566: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing HW Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:580: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Changing BlueALSA PCM configuration: 2 ch, 48000 Hz -> 2 ch, 44100 Hz Dec 12 16:43:21 volumio bluealsa[899]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.SelectCodec() on /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink Dec 12 16:43:21 volumio bluealsa[899]: ../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.ClearConfiguration() on /org/bluez/hci0/A2DP/SBC/source/1 Dec 12 16:43:21 volumio bluealsa[899]: bluez.c:615: Disconnecting media endpoint: /org/bluez/hci0/A2DP/SBC/source/1 Dec 12 16:43:21 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_08_EB_ED_25_4F_D6/sep1/fd0, ...) Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:21 volumio bluealsa[899]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_08_EB_ED_25_4F_D6/sep1/fd1, ...) Dec 12 16:43:21 volumio bluealsa[899]: ../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/source/1 Dec 12 16:43:21 volumio bluealsa[899]: ../src/a2dp-sbc.c:536: SBC: Selected bit-pool range: [2, 53] Dec 12 16:43:21 volumio bluealsa[899]: bluez.c:572: A2DP Source (SBC) configured for device 08:EB:ED:25:4F:D6 Dec 12 16:43:21 volumio bluealsa[899]: bluez.c:575: A2DP selected configuration blob [len=4]: 21150235 Dec 12 16:43:21 volumio bluealsa[899]: bluez.c:577: PCM configuration: channels: 2, sampling: 44100 Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:21 volumio bluealsa[899]: ../src/ba-transport.c:826: Freeing transport: A2DP Source (SBC) Dec 12 16:43:21 volumio bluealsa[899]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink Dec 12 16:43:21 volumio bluetoothd[681]: /org/bluez/hci0/dev_08_EB_ED_25_4F_D6/sep1/fd1: fd(27) ready Dec 12 16:43:21 volumio bluealsa[899]: ../src/ba-transport.c:319: New A2DP transport: 13 Dec 12 16:43:21 volumio bluealsa[899]: ../src/ba-transport.c:320: A2DP socket MTU: 13: R:1021 W:672 Dec 12 16:43:21 volumio bluealsa[899]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Dec 12 16:43:21 volumio bluealsa[899]: ../src/ba-transport.c:1075: Starting transport: A2DP Source (SBC) Dec 12 16:43:21 volumio bluealsa[899]: ../src/ba-transport-pcm.c:294: Created BT socket duplicate: [13]: 14 Dec 12 16:43:21 volumio bluealsa[899]: ../src/ba-transport-pcm.c:373: Created new IO thread [ba-a2dp-sbc]: A2DP Source (SBC) Dec 12 16:43:21 volumio bluealsa[899]: ../src/codec-sbc.c:278: SBC setup: 44100 Hz JointStereo allocation=Loudness blocks=16 sub-bands=8 bit-pool=53 => 327993 bps Dec 12 16:43:21 volumio bluealsa[899]: ../src/a2dp-sbc.c:191: PCM IO loop: START: a2dp_sbc_enc_thread: A2DP Source (SBC) Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:631: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: FIFO buffer size: 1024 frames Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:636: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Selected HW buffer: 4 periods x 22048 bytes <= 88200 bytes Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Prepared Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124989 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Initializing SW Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:428: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Stopping Dec 12 16:43:21 volumio go-librespot[1615]: [1635] D: bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Prepared Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=info msg="loaded track \"BIRDS OF A FEATHER\" (paused: false, position: 0ms, duration: 210373ms, prefetched: false)" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:21 volumio bluealsa[899]: ../src/ba-transport-pcm.c:524: PCM drop: 9 Dec 12 16:43:21 volumio go-librespot[1615]: [5331] D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Starting Dec 12 16:43:21 volumio go-librespot[1615]: [5335] D: bluealsa-pcm.c:235: /org/bluealsa/hci0/dev_08_EB_ED_25_4F_D6/a2dpsrc/sink: Starting IO loop: 22 Dec 12 16:43:21 volumio bluealsa[899]: ../src/ba-transport-pcm.c:480: PCM resume: 9 Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=trace msg="scheduling prefetch in 180s" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=trace msg="emitting websocket event: metadata" Dec 12 16:43:21 volumio volumio[1183]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","name":"BIRDS OF A FEATHER","artist_names":["Billie Eilish"],"album_name":"HIT ME HARD AND SOFT","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0271d62ea7ea8a5be92d3c1f62","position":0,"duration":210373,"release_date":"year:2024 month:5 day:17","track_number":4,"disc_number":1}} Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 12 16:43:21 volumio go-librespot[1615]: time="2025-12-12T16:43:21+01:00" level=trace msg="emitting websocket event: playing" Dec 12 16:43:21 volumio volumio[1183]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","resume":false,"play_origin":"go-librespot"}} Dec 12 16:43:21 volumio volumio[1183]: SPOTIFY: PUSH STATE SPOTIFY Dec 12 16:43:21 volumio volumio[1183]: SPOTIFY: {"status":"play","service":"spop","title":"BIRDS OF A FEATHER","artist":"Billie Eilish","album":"HIT ME HARD AND SOFT","albumart":"https://i.scdn.co/image/ab67616d00001e0271d62ea7ea8a5be92d3c1f62","uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 16:43:21 volumio volumio[1183]: info: CoreCommandRouter::servicePushState Dec 12 16:43:21 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:43:21 volumio volumio[1183]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"BIRDS OF A FEATHER","artist":"Billie Eilish","album":"HIT ME HARD AND SOFT","albumart":"https://i.scdn.co/image/ab67616d00001e0271d62ea7ea8a5be92d3c1f62","uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 16:43:21 volumio volumio[1183]: verbose: CURRENT POSITION 0 Dec 12 16:43:21 volumio volumio[1183]: info: CoreStateMachine::syncState stateService play Dec 12 16:43:21 volumio volumio[1183]: info: CoreStateMachine::syncState currentStatus stop Dec 12 16:43:21 volumio volumio[1183]: SPOTIFY: PUSH STATE SPOTIFY Dec 12 16:43:21 volumio volumio[1183]: SPOTIFY: {"status":"play","service":"spop","title":"BIRDS OF A FEATHER","artist":"Billie Eilish","album":"HIT ME HARD AND SOFT","albumart":"https://i.scdn.co/image/ab67616d00001e0271d62ea7ea8a5be92d3c1f62","uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 16:43:21 volumio volumio[1183]: info: CoreCommandRouter::servicePushState Dec 12 16:43:21 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:43:21 volumio volumio[1183]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"BIRDS OF A FEATHER","artist":"Billie Eilish","album":"HIT ME HARD AND SOFT","albumart":"https://i.scdn.co/image/ab67616d00001e0271d62ea7ea8a5be92d3c1f62","uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","trackType":"spotify","seek":0,"duration":210,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 12 16:43:21 volumio volumio[1183]: verbose: CURRENT POSITION 0 Dec 12 16:43:21 volumio volumio[1183]: info: CoreStateMachine::syncState stateService play Dec 12 16:43:21 volumio volumio[1183]: info: CoreStateMachine::syncState currentStatus play Dec 12 16:43:21 volumio volumio[1183]: info: Received an update from plugin. extracting info from payload Dec 12 16:43:21 volumio volumio[1183]: info: CoreStateMachine::pushState Dec 12 16:43:21 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:43:21 volumio volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 16:43:21 volumio volumio[1183]: info: CoreCommandRouter::volumioPushState Dec 12 16:43:22 volumio volumio[1183]: info: CoreStateMachine::pushState Dec 12 16:43:22 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:43:22 volumio volumio[1183]: info: CoreCommandRouter::volumioPushState Dec 12 16:43:22 volumio volumio[1183]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Dec 12 16:43:22 volumio volumio[1183]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Dec 12 16:43:25 volumio thd[5292]: Error reading device '/dev/input/event0' Dec 12 16:43:25 volumio systemd[1]: Stopping triggerhappy.service - triggerhappy global hotkey daemon... Dec 12 16:43:27 volumio go-librespot[1615]: time="2025-12-12T16:43:27+01:00" level=trace msg="received accesspoint ping" Dec 12 16:43:27 volumio go-librespot[1615]: time="2025-12-12T16:43:27+01:00" level=trace msg="received accesspoint pong ack" Dec 12 16:43:27 volumio go-librespot[1615]: time="2025-12-12T16:43:27+01:00" level=trace msg="sent dealer ping" Dec 12 16:43:27 volumio go-librespot[1615]: time="2025-12-12T16:43:27+01:00" level=trace msg="received dealer pong" Dec 12 16:43:29 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_54_80_77_E2_7A_66, ...) Dec 12 16:43:29 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_63_D8_23_D8_8E_72, ...) Dec 12 16:43:29 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6C_70_81_00_E0_1C, ...) Dec 12 16:43:29 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6E_F1_7E_DB_5B_AF, ...) Dec 12 16:43:29 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6E_57_D6_20_52_AC, ...) Dec 12 16:43:30 volumio kernel: input: SoundCore 2 (AVRCP) as /devices/virtual/input/input1 Dec 12 16:43:30 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_4E_36_92_C7_0E_58, ...) Dec 12 16:43:30 volumio bluealsa[899]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_7C_45_7D_E7_EB_58, ...) Dec 12 16:43:30 volumio systemd[1]: triggerhappy.service: Deactivated successfully. Dec 12 16:43:30 volumio systemd[1]: Stopped triggerhappy.service - triggerhappy global hotkey daemon. Dec 12 16:43:31 volumio systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... Dec 12 16:43:31 volumio thd[5358]: Unable to parse trigger line: Dec 12 16:43:31 volumio thd[5358]: Unable to parse trigger line: Dec 12 16:43:31 volumio systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. Dec 12 16:43:31 volumio systemd[1]: Stopping triggerhappy.service - triggerhappy global hotkey daemon... Dec 12 16:43:31 volumio systemd[1]: triggerhappy.service: Deactivated successfully. Dec 12 16:43:31 volumio systemd[1]: Stopped triggerhappy.service - triggerhappy global hotkey daemon. Dec 12 16:43:31 volumio systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... Dec 12 16:43:31 volumio thd[5361]: Unable to parse trigger line: Dec 12 16:43:31 volumio thd[5361]: Unable to parse trigger line: Dec 12 16:43:31 volumio systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. Dec 12 16:43:31 volumio systemd-logind[690]: Watching system buttons on /dev/input/event0 (SoundCore 2 (AVRCP)) Dec 12 16:43:33 volumio go-librespot[1615]: time="2025-12-12T16:43:33+01:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:45 volumio go-librespot[1615]: time="2025-12-12T16:43:45+01:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:43:57 volumio go-librespot[1615]: time="2025-12-12T16:43:57+01:00" level=trace msg="sent dealer ping" Dec 12 16:43:57 volumio go-librespot[1615]: time="2025-12-12T16:43:57+01:00" level=trace msg="received dealer pong" Dec 12 16:43:57 volumio go-librespot[1615]: time="2025-12-12T16:43:57+01:00" level=debug msg="fetched chunk 6/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:44:10 volumio go-librespot[1615]: time="2025-12-12T16:44:10+01:00" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:44:15 volumio volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 12 16:44:15 volumio volumio[1183]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 12 16:44:18 volumio volumio[1183]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 12 16:44:22 volumio go-librespot[1615]: time="2025-12-12T16:44:22+01:00" level=debug msg="fetched chunk 8/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:44:27 volumio go-librespot[1615]: time="2025-12-12T16:44:27+01:00" level=trace msg="sent dealer ping" Dec 12 16:44:27 volumio go-librespot[1615]: time="2025-12-12T16:44:27+01:00" level=trace msg="received dealer pong" Dec 12 16:44:34 volumio volumio[1183]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 12 16:44:34 volumio volumio[1183]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 12 16:44:34 volumio volumio[1183]: info: Creating Spotify config file Dec 12 16:44:34 volumio volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:44:34 volumio volumio[1183]: info: Spotify config file written Dec 12 16:44:34 volumio go-librespot[1615]: time="2025-12-12T16:44:34+01:00" level=debug msg="fetched chunk 9/17, size: 524288" uri="spotify:track:6dOtVTDdiauQNBQEDOtlAB" Dec 12 16:44:34 volumio sudo[5479]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 12 16:44:34 volumio sudo[5479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 16:44:34 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 12 16:44:34 volumio bluealsa[899]: ../src/ba-transport-pcm.c:453: Closing PCM: 9 Dec 12 16:44:34 volumio bluealsa[899]: ../src/ba-transport.c:203: PCM clients check keep-alive: 0 ms Dec 12 16:44:34 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 12 16:44:34 volumio bluealsa[899]: ../src/ba-transport.c:148: Stopping transport: No PCM clients Dec 12 16:44:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 16:44:34 volumio systemd[1]: go-librespot-daemon.service: Consumed 5.851s CPU time. Dec 12 16:44:34 volumio bluealsa[899]: ../src/ba-transport-pcm.c:307: Closing BT socket duplicate [13]: 14 Dec 12 16:44:34 volumio bluealsa[899]: ../src/ba-transport.c:346: Releasing A2DP transport: 13 Dec 12 16:44:34 volumio volumio[1183]: info: Connection to go-librespot Websocket closed Dec 12 16:44:34 volumio bluealsa[899]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Dec 12 16:44:34 volumio bluealsa[899]: ../src/ba-transport.c:381: Closing A2DP transport: 13 Dec 12 16:44:34 volumio bluealsa[899]: ../src/ba-transport-pcm.c:257: Exiting IO thread [ba-a2dp-sbc]: A2DP Source (SBC) Dec 12 16:44:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 16:44:34 volumio go-librespot[5482]: go-librespot daemon starting... Dec 12 16:44:34 volumio sudo[5479]: pam_unix(sudo:session): session closed for user root Dec 12 16:44:37 volumio volumio[1183]: info: Initializing connection to go-librespot Websocket Dec 12 16:44:37 volumio volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:44:37 volumio volumio[1183]: info: go-librespot daemon successfully initialized Dec 12 16:44:38 volumio volumio[1183]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 12 16:44:38 volumio volumio[1183]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 12 16:44:38 volumio volumio[1183]: info: Creating Spotify config file Dec 12 16:44:38 volumio volumio[1183]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 12 16:44:38 volumio volumio[1183]: info: Spotify config file written Dec 12 16:44:38 volumio sudo[5490]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 12 16:44:38 volumio sudo[5490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 12 16:44:38 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 12 16:44:38 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 12 16:44:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 16:44:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 16:44:38 volumio go-librespot[5492]: go-librespot daemon starting... Dec 12 16:44:38 volumio sudo[5490]: pam_unix(sudo:session): session closed for user root Dec 12 16:44:40 volumio volumio[1183]: info: Initializing connection to go-librespot Websocket Dec 12 16:44:40 volumio volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:44:40 volumio volumio[1183]: info: Initializing connection to go-librespot Websocket Dec 12 16:44:40 volumio volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:44:41 volumio volumio[1183]: info: CoreCommandRouter::volumioGetState Dec 12 16:44:41 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:44:41 volumio volumio[1183]: info: go-librespot daemon successfully initialized Dec 12 16:44:43 volumio go-librespot[5493]: time="2025-12-12T16:44:43+01:00" level=info msg="running go-librespot ab178ffd" Dec 12 16:44:43 volumio go-librespot[5493]: time="2025-12-12T16:44:43+01:00" level=debug msg="app state loaded" Dec 12 16:44:43 volumio go-librespot[5493]: time="2025-12-12T16:44:43+01:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 12 16:44:43 volumio volumio[1183]: info: Initializing connection to go-librespot Websocket Dec 12 16:44:43 volumio go-librespot[5493]: time="2025-12-12T16:44:43+01:00" level=debug msg="new websocket client" Dec 12 16:44:43 volumio volumio[1183]: info: Connection to go-librespot Websocket established Dec 12 16:44:43 volumio go-librespot[5493]: time="2025-12-12T16:44:43+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 16:44:43 volumio go-librespot[5493]: time="2025-12-12T16:44:43+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 16:44:43 volumio go-librespot[5493]: time="2025-12-12T16:44:43+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 16:44:43 volumio go-librespot[5493]: time="2025-12-12T16:44:43+01:00" level=info msg="zeroconf server listening on port 34097" Dec 12 16:44:44 volumio go-librespot[5493]: time="2025-12-12T16:44:44+01:00" level=debug msg="obtained new client token: AACa8+mRhfWPFimN5FpTGn/7Pc45xHHJ9sOWxt2utSWolYoJkvxL6kRyIqzg585ujZDQMvxOXP7UKwqbX+BzCA9shNrGE4RcmXcd5DZzjOXr7QYSkUjJVFdYd6kJkmUYdlnNuniieNsxNPGVDcnjGyAhPXsp/lngf6tEB6b+R5Y4J1wKCXU8XBXIYC+1YFNhV/J6q7gDKMu3n1woHGyBisljjbxdM9qfXepoKw==" Dec 12 16:44:44 volumio go-librespot[5493]: time="2025-12-12T16:44:44+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Dec 12 16:44:44 volumio go-librespot[5493]: time="2025-12-12T16:44:44+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.178.106:42562->34.158.1.133:4070: read: connection reset by peer" Dec 12 16:44:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 12 16:44:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 12 16:44:44 volumio volumio[1183]: info: Connection to go-librespot Websocket closed Dec 12 16:44:44 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 12 16:44:44 volumio volumio[1183]: info: Initializing connection to go-librespot Websocket Dec 12 16:44:44 volumio volumio[1183]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:44:45 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Dec 12 16:44:45 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Dec 12 16:44:46 volumio volumio[1183]: info: CoreCommandRouter::volumioNext Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::next Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::stop Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::stPlaybackTimer Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::updateTrackBlock Dec 12 16:44:46 volumio volumio[1183]: info: CorePlayQueue::getTrackBlock Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::pushState Dec 12 16:44:46 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:44:46 volumio volumio[1183]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 12 16:44:46 volumio volumio[1183]: info: CoreCommandRouter::volumioPushState Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::serviceStop Dec 12 16:44:46 volumio volumio[1183]: info: CorePlayQueue::getTrack 0 Dec 12 16:44:46 volumio volumio[1183]: info: CoreCommandRouter::serviceStop Dec 12 16:44:46 volumio volumio[1183]: info: Spotify Stop Dec 12 16:44:46 volumio volumio[1183]: SPOTIFY: SPOTIFY STOP Dec 12 16:44:46 volumio volumio[1183]: SPOTIFY: {"status":"play","position":0,"title":"BIRDS OF A FEATHER","artist":"Billie Eilish","album":"HIT ME HARD AND SOFT","albumart":"https://i.scdn.co/image/ab67616d0000b27371d62ea7ea8a5be92d3c1f62","uri":"spotify:track:6dOtVTDdiauQNBQEDOtlAB","trackType":"spotify","codec":"ogg","seek":0,"duration":210,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":85,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Dec 12 16:44:46 volumio volumio[1183]: info: Sending Spotify command to local API: /player/pause Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::play index undefined Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 12 16:44:46 volumio volumio[1183]: info: CorePlayQueue::getTrack 1 Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::startPlaybackTimer Dec 12 16:44:46 volumio volumio[1183]: info: CorePlayQueue::getTrack 1 Dec 12 16:44:46 volumio volumio[1183]: info: [1765554286043] ControllerSpotify::clearAddPlayTrack Dec 12 16:44:46 volumio volumio[1183]: info: Sending Spotify command with payload to local API: /player/play Dec 12 16:44:46 volumio volumio[1183]: info: CoreStateMachine::updateTrackBlock Dec 12 16:44:46 volumio volumio[1183]: info: CorePlayQueue::getTrackBlock Dec 12 16:44:46 volumio volumio[1183]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Dec 12 16:44:46 volumio volumio[1183]: error: Failed to send command to Spotify local API: /player/pause: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:44:46 volumio volumio[1183]: error: Failed to send command to Spotify local API: /player/play: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:44:46 volumio volumio[1183]: info: Getting Spotify volume Dec 12 16:44:46 volumio volumio[1183]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 16:44:46 volumio volumio[1183]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 12 16:44:46 volumio volumio[1183]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 12 16:44:46 volumio volumio[1183]: errno: -111, Dec 12 16:44:46 volumio volumio[1183]: code: 'ECONNREFUSED', Dec 12 16:44:46 volumio volumio[1183]: syscall: 'connect', Dec 12 16:44:46 volumio volumio[1183]: address: '127.0.0.1', Dec 12 16:44:46 volumio volumio[1183]: port: 9879, Dec 12 16:44:46 volumio volumio[1183]: response: undefined Dec 12 16:44:46 volumio volumio[1183]: } Dec 12 16:44:46 volumio volumio[1183]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 12 16:44:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 12 16:44:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 12 16:44:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 12 16:44:47 volumio go-librespot[5562]: go-librespot daemon starting... Dec 12 16:44:47 volumio sudo[5567]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-12 16:43' Dec 12 16:44:47 volumio sudo[5567]: 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"