-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Sat 2025-12-27 23:00:11 CET. -- Dec 27 22:59:00 volumio-wz volumio[915]: info: MRS: STARTING volumioStreaming Dec 27 22:59:00 volumio-wz sudo[12419]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/stream.m3u8 /tmp/hls/stream164.ts /tmp/hls/stream165.ts /tmp/hls/stream166.ts /tmp/hls/stream167.ts /tmp/hls/stream168.ts Dec 27 22:59:00 volumio-wz sudo[12419]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 22:59:00 volumio-wz sudo[12419]: pam_unix(sudo:session): session closed for user root Dec 27 22:59:00 volumio-wz sudo[12422]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Dec 27 22:59:00 volumio-wz sudo[12422]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 22:59:00 volumio-wz systemd[1]: Stopping VolumioStreamingService... Dec 27 22:59:00 volumio-wz systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Dec 27 22:59:00 volumio-wz volumio[915]: ------------------------------------ BT MESSAGE: BT STATUS: running Dec 27 22:59:00 volumio-wz systemd[1]: volumioStreaming.service: Succeeded. Dec 27 22:59:00 volumio-wz systemd[1]: Stopped VolumioStreamingService. Dec 27 22:59:00 volumio-wz volumio[915]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Dec 27 22:59:00 volumio-wz systemd[1]: Started VolumioStreamingService. Dec 27 22:59:00 volumio-wz sudo[12422]: pam_unix(sudo:session): session closed for user root Dec 27 22:59:00 volumio-wz volumio[915]: info: MRS: volumioStreaming STARTED Dec 27 22:59:00 volumio-wz sudo[12425]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 27 22:59:00 volumio-wz sudo[12425]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 22:59:00 volumio-wz sudo[12425]: pam_unix(sudo:session): session closed for user root Dec 27 22:59:06 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:06+01:00" level=trace msg="sent dealer ping" Dec 27 22:59:06 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:06+01:00" level=trace msg="received dealer pong" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=debug msg="handling resume player command from dd94d9b02cfe79aafc3f7bcaa0a74dd4ecd1bca8" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=trace msg="seek to 18861ms (diff: 78ms, samples: 831770, bytes: 372352)" uri="spotify:track:31Qdjy2lPMZvAXzWyE3pZO" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=debug msg="resume track at 18783ms" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=trace msg="scheduling prefetch in 173s" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=debug msg="sending successful reply for dealer request" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:09 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:09+01:00" level=trace msg="emitting websocket event: playing" Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","resume":true,"play_origin":"playlist"}} Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":28512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","resume":true,"play_origin":"playlist"}} Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":28512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","resume":true,"play_origin":"playlist"}} Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":28512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:09 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:09 volumio-wz volumio[915]: info: [GPIO_Control] Handling event: musicPlay Dec 27 22:59:09 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:09 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:09 volumio-wz volumio[915]: info: touch_display: Setting screensaver timeout to 0 seconds. Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":28512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:09 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":28512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:09 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":28512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:09 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:09 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:09 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:09 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:19 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:19+01:00" level=debug msg="fetched chunk 4/8, size: 524288" uri="spotify:track:31Qdjy2lPMZvAXzWyE3pZO" Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPause Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreStateMachine::pause Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreStateMachine::stPlaybackTimer Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreStateMachine::servicePause Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::servicePause Dec 27 22:59:20 volumio-wz volumio[915]: info: Spotify Received pause Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: SPOTIFY PAUSE Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: {"status":"play","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","codec":"ogg","seek":28512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":49,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Dec 27 22:59:20 volumio-wz volumio[915]: info: Sending Spotify command to local API: /player/pause Dec 27 22:59:20 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:20+01:00" level=debug msg="pause track at 25596ms" Dec 27 22:59:20 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:20 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:20 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:20+01:00" level=trace msg="emitting websocket event: paused" Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","play_origin":"playlist"}} Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: {"status":"pause","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":39512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:20 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:20 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","play_origin":"playlist"}} Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: {"status":"pause","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":39512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:20 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:20 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","play_origin":"playlist"}} Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: {"status":"pause","service":"spop","title":"Touch In The Night","artist":"2DCAT, HAEZL","album":"Touch In The Night","albumart":"https://i.scdn.co/image/ab67616d00001e02058ad02124a2a8fc1bd629c7","uri":"spotify:track:31Qdjy2lPMZvAXzWyE3pZO","trackType":"spotify","seek":39512,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:20 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:20 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:20 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:20 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: pause Dec 27 22:59:20 volumio-wz volumio[915]: info: [GPIO_Control] Handling event: musicPause Dec 27 22:59:20 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: pause Dec 27 22:59:20 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: pause Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:20 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:20 volumio-wz volumio[915]: info: touch_display: Setting screensaver timeout to 120 seconds. Dec 27 22:59:23 volumio-wz volumio[915]: info: MRS: STARTING volumioStreaming Dec 27 22:59:23 volumio-wz sudo[12526]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/stream.m3u8 /tmp/hls/stream17.ts /tmp/hls/stream18.ts /tmp/hls/stream19.ts /tmp/hls/stream20.ts /tmp/hls/stream21.ts Dec 27 22:59:23 volumio-wz sudo[12526]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 22:59:23 volumio-wz sudo[12526]: pam_unix(sudo:session): session closed for user root Dec 27 22:59:23 volumio-wz sudo[12529]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Dec 27 22:59:23 volumio-wz sudo[12529]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 22:59:23 volumio-wz systemd[1]: Stopping VolumioStreamingService... Dec 27 22:59:23 volumio-wz systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Dec 27 22:59:23 volumio-wz volumio[915]: ------------------------------------ BT MESSAGE: BT STATUS: running Dec 27 22:59:23 volumio-wz systemd[1]: volumioStreaming.service: Succeeded. Dec 27 22:59:23 volumio-wz systemd[1]: Stopped VolumioStreamingService. Dec 27 22:59:23 volumio-wz volumio[915]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Dec 27 22:59:23 volumio-wz systemd[1]: Started VolumioStreamingService. Dec 27 22:59:23 volumio-wz sudo[12529]: pam_unix(sudo:session): session closed for user root Dec 27 22:59:23 volumio-wz volumio[915]: info: MRS: volumioStreaming STARTED Dec 27 22:59:23 volumio-wz sudo[12532]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 27 22:59:23 volumio-wz sudo[12532]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 22:59:23 volumio-wz sudo[12532]: pam_unix(sudo:session): session closed for user root Dec 27 22:59:36 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:36+01:00" level=trace msg="sent dealer ping" Dec 27 22:59:36 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:36+01:00" level=trace msg="received dealer pong" Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 27 22:59:40 volumio-wz volumio[915]: info: Retrieving Cloud Streaming UI Dec 27 22:59:40 volumio-wz volumio[915]: info: Getting Tidal Cloud Configuration Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 27 22:59:40 volumio-wz volumio[915]: info: Getting Qobuz Cloud Configuration Dec 27 22:59:40 volumio-wz volumio[915]: info: Asking plugin for UI Config Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 27 22:59:40 volumio-wz volumio[915]: info: Getting Spotify Cloud Configuration Dec 27 22:59:40 volumio-wz volumio[915]: info: Asking plugin for UI Config Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 27 22:59:40 volumio-wz volumio[915]: info: Saving Spotify Acccount Dec 27 22:59:40 volumio-wz volumio[915]: info: Got it Dec 27 22:59:40 volumio-wz volumio[915]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Dec 27 22:59:40 volumio-wz volumio[915]: info: Got Tidal Cloud Configuration Dec 27 22:59:40 volumio-wz volumio[915]: info: Got it Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::volumioGetBrowseSources Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::volumioGetBrowseSources Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::volumioGetBrowseSources Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 27 22:59:40 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Dec 27 22:59:44 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 27 22:59:48 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::volumioNext Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreStateMachine::next Dec 27 22:59:52 volumio-wz volumio[915]: info: Spotify next Dec 27 22:59:52 volumio-wz volumio[915]: info: Sending Spotify command to local API: /player/next Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=trace msg="emitting websocket event: will_play" Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","play_origin":"playlist"}} Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","play_origin":"playlist"}} Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="selected format OGG_VORBIS_160 (d42b6e73e976fb59d224a7687915f708559cc8f6)" uri="spotify:track:5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="requested aes key for file d42b6e73e976fb59d224a7687915f708559cc8f6, gid: 5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="fetched first chunk of 8, total size is 4146093 bytes" uri="spotify:track:5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=info msg="loaded track \"All I Want - Das Ich Remix\" (paused: false, position: 0ms, duration: 206896ms, prefetched: false)" uri="spotify:track:5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="fetched chunk 1/7, size: 524288" uri="spotify:track:5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=trace msg="scheduling prefetch in 177s" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=trace msg="emitting websocket event: metadata" Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","name":"All I Want - Das Ich Remix","artist_names":["Diva Destruction","Das Ich"],"album_name":"All I Want (Das Ich Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","position":0,"duration":206896,"release_date":"year:2025 month:12 day:1","track_number":1,"disc_number":1}} Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","name":"All I Want - Das Ich Remix","artist_names":["Diva Destruction","Das Ich"],"album_name":"All I Want (Das Ich Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","position":0,"duration":206896,"release_date":"year:2025 month:12 day:1","track_number":1,"disc_number":1}} Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","name":"All I Want - Das Ich Remix","artist_names":["Diva Destruction","Das Ich"],"album_name":"All I Want (Das Ich Remix)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","position":0,"duration":206896,"release_date":"year:2025 month:12 day:1","track_number":1,"disc_number":1}} Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="fetched chunk 3/7, size: 524288" uri="spotify:track:5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=trace msg="emitting websocket event: playing" Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","resume":false,"play_origin":"playlist"}} Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:52 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:52 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","resume":false,"play_origin":"playlist"}} Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:52 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:52 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","resume":false,"play_origin":"playlist"}} Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:52 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:52 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:52 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:52 volumio-wz volumio[915]: info: [GPIO_Control] Handling event: musicPlay Dec 27 22:59:52 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:52 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:52 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:52+01:00" level=debug msg="fetched chunk 2/7, size: 524288" uri="spotify:track:5k9QFM25HMm4qegc4Dic6j" Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:52 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:52 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 27 22:59:52 volumio-wz volumio[915]: info: touch_display: Setting screensaver timeout to 0 seconds. Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:53 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:53 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:53 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:53 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:53 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:53 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: {"status":"play","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:53 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:53 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:53 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:53 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: play Dec 27 22:59:53 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPause Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreStateMachine::pause Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreStateMachine::stPlaybackTimer Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreStateMachine::servicePause Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::servicePause Dec 27 22:59:56 volumio-wz volumio[915]: info: Spotify Received pause Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: SPOTIFY PAUSE Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: {"status":"play","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","codec":"ogg","seek":0,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":49,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Dec 27 22:59:56 volumio-wz volumio[915]: info: Sending Spotify command to local API: /player/pause Dec 27 22:59:56 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:56+01:00" level=debug msg="pause track at 1594ms" Dec 27 22:59:56 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 27 22:59:56 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 27 22:59:56 volumio-wz go-librespot[10886]: time="2025-12-27T22:59:56+01:00" level=trace msg="emitting websocket event: paused" Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","play_origin":"playlist"}} Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: {"status":"pause","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":4000,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:56 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:56 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","play_origin":"playlist"}} Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: {"status":"pause","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":4000,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:56 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:56 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:49uSLoD72UagzivVIkNgYV","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","play_origin":"playlist"}} Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: PUSH STATE SPOTIFY Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: {"status":"pause","service":"spop","title":"All I Want - Das Ich Remix","artist":"Diva Destruction, Das Ich","album":"All I Want (Das Ich Remix)","albumart":"https://i.scdn.co/image/ab67616d00001e0249c454343454dc2c7b71f43d","uri":"spotify:track:5k9QFM25HMm4qegc4Dic6j","trackType":"spotify","seek":4000,"duration":206,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::servicePushState Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreStateMachine::pushState Dec 27 22:59:56 volumio-wz volumio[915]: info: CoreCommandRouter::volumioPushState Dec 27 22:59:56 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output update for this device Dec 27 22:59:56 volumio-wz volumio[915]: info: MRS: Pushing multiroomSync output Dec 27 22:59:56 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: pause Dec 27 22:59:56 volumio-wz volumio[915]: info: [GPIO_Control] Handling event: musicPause Dec 27 22:59:56 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: pause Dec 27 22:59:56 volumio-wz volumio[915]: info: [GPIO_Control] Status changed: pause Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:56 volumio-wz volumio[915]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Dec 27 22:59:57 volumio-wz volumio[915]: info: touch_display: Setting screensaver timeout to 120 seconds. Dec 27 22:59:59 volumio-wz volumio[915]: info: MRS: STARTING volumioStreaming Dec 27 22:59:59 volumio-wz sudo[12617]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/stream.m3u8 /tmp/hls/stream32.ts /tmp/hls/stream33.ts /tmp/hls/stream34.ts /tmp/hls/stream35.ts /tmp/hls/stream36.ts Dec 27 22:59:59 volumio-wz sudo[12617]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 22:59:59 volumio-wz sudo[12617]: pam_unix(sudo:session): session closed for user root Dec 27 22:59:59 volumio-wz sudo[12620]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioStreaming Dec 27 22:59:59 volumio-wz sudo[12620]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 22:59:59 volumio-wz systemd[1]: Stopping VolumioStreamingService... Dec 27 22:59:59 volumio-wz systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Dec 27 22:59:59 volumio-wz volumio[915]: ------------------------------------ BT MESSAGE: BT STATUS: running Dec 27 23:00:00 volumio-wz systemd[1]: volumioStreaming.service: Succeeded. Dec 27 23:00:00 volumio-wz systemd[1]: Stopped VolumioStreamingService. Dec 27 23:00:00 volumio-wz volumio[915]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Dec 27 23:00:00 volumio-wz systemd[1]: Started VolumioStreamingService. Dec 27 23:00:00 volumio-wz sudo[12620]: pam_unix(sudo:session): session closed for user root Dec 27 23:00:00 volumio-wz volumio[915]: info: MRS: volumioStreaming STARTED Dec 27 23:00:00 volumio-wz sudo[12623]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 27 23:00:00 volumio-wz sudo[12623]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 23:00:00 volumio-wz sudo[12623]: pam_unix(sudo:session): session closed for user root Dec 27 23:00:00 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Dec 27 23:00:02 volumio-wz volumio[915]: info: CoreCommandRouter::volumioGetState Dec 27 23:00:04 volumio-wz volumio[915]: info: Tunnel connection is inactive, restarting it Dec 27 23:00:04 volumio-wz volumio[915]: info: Starting Tunnel 1 Dec 27 23:00:04 volumio-wz volumio[915]: info: Starting Tunnel Connection Checker Dec 27 23:00:04 volumio-wz sudo[12636]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 27 23:00:04 volumio-wz sudo[12636]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 27 23:00:04 volumio-wz systemd[1]: Started MyVolumio SSH Tunnel. Dec 27 23:00:04 volumio-wz sudo[12636]: pam_unix(sudo:session): session closed for user root Dec 27 23:00:04 volumio-wz volumio[915]: info: Remote SSH Started Dec 27 23:00:04 volumio-wz autossh[12639]: port set to 0, monitoring disabled Dec 27 23:00:04 volumio-wz autossh[12639]: starting ssh (count 1) Dec 27 23:00:04 volumio-wz autossh[12639]: ssh child pid is 12642 Dec 27 23:00:04 volumio-wz volumio[915]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Dec 27 23:00:04 volumio-wz volumio[915]: info: CoreCommandRouter::volumioGetState Dec 27 23:00:04 volumio-wz volumiossh-tunnel[12638]: Warning: Permanently added '[eu10.myvolumio.org]:2222,[46.101.141.203]:2222' (RSA) to the list of known hosts. Dec 27 23:00:04 volumio-wz volumio[915]: info: Executing endpoint metavolumio Dec 27 23:00:04 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 27 23:00:04 volumio-wz volumio[915]: info: Executing endpoint metavolumio Dec 27 23:00:04 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 27 23:00:04 volumio-wz volumio[915]: info: Executing endpoint metavolumio Dec 27 23:00:04 volumio-wz volumio[915]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Dec 27 23:00:04 volumio-wz volumiossh-tunnel[12638]: Connection to eu10.myvolumio.org closed by remote host. Dec 27 23:00:04 volumio-wz autossh[12639]: ssh exited prematurely with status 255; autossh exiting Dec 27 23:00:04 volumio-wz systemd[1]: sshtunnel.service: Main process exited, code=exited, status=1/FAILURE Dec 27 23:00:04 volumio-wz systemd[1]: sshtunnel.service: Failed with result 'exit-code'. Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Service RestartSec=100ms expired, scheduling restart. Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Scheduled restart job, restart counter is at 1. Dec 27 23:00:05 volumio-wz systemd[1]: Stopped MyVolumio SSH Tunnel. Dec 27 23:00:05 volumio-wz systemd[1]: Started MyVolumio SSH Tunnel. Dec 27 23:00:05 volumio-wz autossh[12712]: port set to 0, monitoring disabled Dec 27 23:00:05 volumio-wz autossh[12712]: starting ssh (count 1) Dec 27 23:00:05 volumio-wz autossh[12712]: ssh child pid is 12715 Dec 27 23:00:05 volumio-wz volumiossh-tunnel[12711]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 27 23:00:05 volumio-wz autossh[12712]: ssh exited prematurely with status 255; autossh exiting Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Main process exited, code=exited, status=1/FAILURE Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Failed with result 'exit-code'. Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Service RestartSec=100ms expired, scheduling restart. Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Scheduled restart job, restart counter is at 2. Dec 27 23:00:05 volumio-wz systemd[1]: Stopped MyVolumio SSH Tunnel. Dec 27 23:00:05 volumio-wz systemd[1]: Started MyVolumio SSH Tunnel. Dec 27 23:00:05 volumio-wz autossh[12717]: port set to 0, monitoring disabled Dec 27 23:00:05 volumio-wz autossh[12717]: starting ssh (count 1) Dec 27 23:00:05 volumio-wz autossh[12717]: ssh child pid is 12720 Dec 27 23:00:05 volumio-wz volumiossh-tunnel[12716]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 27 23:00:05 volumio-wz autossh[12717]: ssh exited prematurely with status 255; autossh exiting Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Main process exited, code=exited, status=1/FAILURE Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Failed with result 'exit-code'. Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Service RestartSec=100ms expired, scheduling restart. Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Scheduled restart job, restart counter is at 3. Dec 27 23:00:05 volumio-wz systemd[1]: Stopped MyVolumio SSH Tunnel. Dec 27 23:00:05 volumio-wz systemd[1]: Started MyVolumio SSH Tunnel. Dec 27 23:00:05 volumio-wz autossh[12722]: port set to 0, monitoring disabled Dec 27 23:00:05 volumio-wz autossh[12722]: starting ssh (count 1) Dec 27 23:00:05 volumio-wz autossh[12722]: ssh child pid is 12725 Dec 27 23:00:05 volumio-wz volumiossh-tunnel[12721]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 27 23:00:05 volumio-wz autossh[12722]: ssh exited prematurely with status 255; autossh exiting Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Main process exited, code=exited, status=1/FAILURE Dec 27 23:00:05 volumio-wz systemd[1]: sshtunnel.service: Failed with result 'exit-code'. Dec 27 23:00:06 volumio-wz systemd[1]: sshtunnel.service: Service RestartSec=100ms expired, scheduling restart. Dec 27 23:00:06 volumio-wz systemd[1]: sshtunnel.service: Scheduled restart job, restart counter is at 4. Dec 27 23:00:06 volumio-wz systemd[1]: Stopped MyVolumio SSH Tunnel. Dec 27 23:00:06 volumio-wz systemd[1]: Started MyVolumio SSH Tunnel. Dec 27 23:00:06 volumio-wz autossh[12728]: port set to 0, monitoring disabled Dec 27 23:00:06 volumio-wz autossh[12728]: starting ssh (count 1) Dec 27 23:00:06 volumio-wz autossh[12728]: ssh child pid is 12731 Dec 27 23:00:06 volumio-wz volumiossh-tunnel[12726]: ssh: connect to host eu10.myvolumio.org port 2222: Connection refused Dec 27 23:00:06 volumio-wz autossh[12728]: ssh exited prematurely with status 255; autossh exiting Dec 27 23:00:06 volumio-wz systemd[1]: sshtunnel.service: Main process exited, code=exited, status=1/FAILURE Dec 27 23:00:06 volumio-wz systemd[1]: sshtunnel.service: Failed with result 'exit-code'. Dec 27 23:00:06 volumio-wz systemd[1]: sshtunnel.service: Service RestartSec=100ms expired, scheduling restart. Dec 27 23:00:06 volumio-wz systemd[1]: sshtunnel.service: Scheduled restart job, restart counter is at 5. Dec 27 23:00:06 volumio-wz systemd[1]: Stopped MyVolumio SSH Tunnel. Dec 27 23:00:06 volumio-wz systemd[1]: sshtunnel.service: Start request repeated too quickly. Dec 27 23:00:06 volumio-wz systemd[1]: sshtunnel.service: Failed with result 'exit-code'. Dec 27 23:00:06 volumio-wz systemd[1]: Failed to start MyVolumio SSH Tunnel. Dec 27 23:00:06 volumio-wz go-librespot[10886]: time="2025-12-27T23:00:06+01:00" level=trace msg="sent dealer ping" Dec 27 23:00:06 volumio-wz go-librespot[10886]: time="2025-12-27T23:00:06+01:00" level=trace msg="received dealer pong" Dec 27 23:00:11 volumio-wz volumio[915]: info: [1766872811504] [80s80s] Pushing the next song state Depeche Mode - Shake the Disease and getting next track. Dec 27 23:00:11 volumio-wz volumio[915]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 27 23:00:11 volumio-wz volumio[915]: TypeError: Cannot set property 'name' of undefined Dec 27 23:00:11 volumio-wz volumio[915]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Dec 27 23:00:11 volumio-wz volumio[915]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Dec 27 23:00:11 volumio-wz volumio[915]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Dec 27 23:00:11 volumio-wz volumio[915]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Dec 27 23:00:11 volumio-wz volumio[915]: at processImmediate (internal/timers.js:461:21) Dec 27 23:00:11 volumio-wz volumio[915]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 27 23:00:11 volumio-wz sudo[12741]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-27 22:59 Dec 27 23:00:11 volumio-wz sudo[12741]: 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="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 05:43:24 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="15d0241b0cd805792809f3ddf4a0fc4e"