-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Thu 2025-05-15 22:52:38 CEST. -- May 15 22:51:02 volumiobe systemd[1582]: run-docker-runtime\x2drunc-moby-950a2e81e2d2ea6f7ac18e967e92d826980424914f2e0b243af694e01a3a3502-runc.prKUbg.mount: Succeeded. May 15 22:51:02 volumiobe systemd[1]: run-docker-runtime\x2drunc-moby-950a2e81e2d2ea6f7ac18e967e92d826980424914f2e0b243af694e01a3a3502-runc.prKUbg.mount: Succeeded. May 15 22:51:02 volumiobe containerd[775]: time="2025-05-15T22:51:02.313410167+02:00" level=error msg="add cg to OOM monitor" error="cgroups: memory cgroup not supported on this system" May 15 22:51:09 volumiobe docker[1305]: pydPiper starting May 15 22:51:09 volumiobe docker[1305]: Uncaught exception May 15 22:51:09 volumiobe docker[1305]: Traceback (most recent call last): May 15 22:51:09 volumiobe docker[1305]: File "/app/pydPiper.py", line 615, in May 15 22:51:09 volumiobe docker[1305]: lcd = displays.hd44780_i2c.hd44780_i2c(rows, cols, i2c_address, i2c_port) May 15 22:51:09 volumiobe docker[1305]: File "/app/displays/hd44780_i2c.py", line 134, in __init__ May 15 22:51:09 volumiobe docker[1305]: self.write4bits(0x33,False) May 15 22:51:09 volumiobe docker[1305]: File "/app/displays/hd44780_i2c.py", line 160, in write4bits May 15 22:51:09 volumiobe docker[1305]: self.bus.write_byte(self.i2c_addr, bits_high) May 15 22:51:09 volumiobe docker[1305]: IOError: [Errno 5] Input/output error May 15 22:51:09 volumiobe docker[1305]: Loading font from /app/displays/fonts/latin1_5x8_fixed.fnt May 15 22:51:09 volumiobe docker[1305]: Traceback (most recent call last): May 15 22:51:09 volumiobe docker[1305]: File "/app/pydPiper.py", line 615, in May 15 22:51:09 volumiobe docker[1305]: lcd = displays.hd44780_i2c.hd44780_i2c(rows, cols, i2c_address, i2c_port) May 15 22:51:09 volumiobe docker[1305]: File "/app/displays/hd44780_i2c.py", line 134, in __init__ May 15 22:51:09 volumiobe docker[1305]: self.write4bits(0x33,False) May 15 22:51:09 volumiobe docker[1305]: File "/app/displays/hd44780_i2c.py", line 160, in write4bits May 15 22:51:09 volumiobe docker[1305]: self.bus.write_byte(self.i2c_addr, bits_high) May 15 22:51:09 volumiobe docker[1305]: IOError: [Errno 5] Input/output error May 15 22:51:09 volumiobe containerd[775]: time="2025-05-15T22:51:09.623874597+02:00" level=info msg="shim disconnected" id=950a2e81e2d2ea6f7ac18e967e92d826980424914f2e0b243af694e01a3a3502 May 15 22:51:09 volumiobe containerd[775]: time="2025-05-15T22:51:09.624412774+02:00" level=warning msg="cleaning up after shim disconnected" id=950a2e81e2d2ea6f7ac18e967e92d826980424914f2e0b243af694e01a3a3502 namespace=moby May 15 22:51:09 volumiobe dockerd[854]: time="2025-05-15T22:51:09.624935587+02:00" level=info msg="ignoring event" container=950a2e81e2d2ea6f7ac18e967e92d826980424914f2e0b243af694e01a3a3502 module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete" May 15 22:51:09 volumiobe containerd[775]: time="2025-05-15T22:51:09.624472514+02:00" level=info msg="cleaning up dead shim" May 15 22:51:09 volumiobe containerd[775]: time="2025-05-15T22:51:09.663605435+02:00" level=warning msg="cleanup warnings time=\"2025-05-15T22:51:09+02:00\" level=info msg=\"starting signal loop\" namespace=moby pid=2901 runtime=io.containerd.runc.v2\n" May 15 22:51:09 volumiobe systemd[1]: pydpiper.service: Main process exited, code=exited, status=1/FAILURE May 15 22:51:09 volumiobe systemd[1]: pydpiper.service: Failed with result 'exit-code'. May 15 22:51:10 volumiobe systemd[1]: pydpiper.service: Service RestartSec=100ms expired, scheduling restart. May 15 22:51:10 volumiobe systemd[1]: pydpiper.service: Scheduled restart job, restart counter is at 1. May 15 22:51:10 volumiobe systemd[1]: Stopped pydPiper container. May 15 22:51:10 volumiobe systemd[1]: Started pydPiper container. May 15 22:51:37 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 15 22:51:37 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 15 22:51:37 volumiobe volumio[1303]: info: CoreCommandRouter::getUIConfigOnPlugin May 15 22:51:37 volumiobe volumio[1303]: Upnp client error: Error: This socket has been ended by the other party May 15 22:51:37 volumiobe volumio[1303]: Upnp client error: Error: This socket has been ended by the other party May 15 22:51:37 volumiobe volumio[1303]: Upnp client error: Error: This socket has been ended by the other party May 15 22:51:37 volumiobe volumio[1303]: Upnp client error: Error: This socket has been ended by the other party May 15 22:51:37 volumiobe volumio[1303]: info: CoreCommandRouter::getUIConfigOnPlugin May 15 22:51:37 volumiobe volumio[1303]: info: CoreCommandRouter::getUIConfigOnPlugin May 15 22:51:37 volumiobe volumio[1303]: info: FusionDsp - May 15 22:51:37 volumiobe volumio[1303]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 15 22:51:37 volumiobe volumio[1303]: info: FusionDsp - May 15 22:51:38 volumiobe volumio[1303]: info: FusionDsp - May 15 22:51:38 volumiobe volumio[1303]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 15 22:51:38 volumiobe volumio[1303]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 15 22:51:43 volumiobe volumio[1303]: info: CoreCommandRouter::getUIConfigOnPlugin May 15 22:51:43 volumiobe volumio[1303]: info: [ASDebug] Setting UI defaults May 15 22:51:43 volumiobe volumio[1303]: info: [ASDebug] Port: 4 May 15 22:51:43 volumiobe volumio[1303]: info: [ASDebug] Inverted: false May 15 22:51:43 volumiobe volumio[1303]: info: [ASDebug] Latched: false May 15 22:51:43 volumiobe volumio[1303]: info: [ASDebug] On pulse width: 500 May 15 22:51:43 volumiobe volumio[1303]: info: [ASDebug] Off pulse width: 500 May 15 22:51:46 volumiobe volumio[1303]: Upnp client error: Error: This socket has been ended by the other party May 15 22:51:58 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 0 May 15 22:51:58 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:51:58 volumiobe volumio[1303]: info: Prefetching next song May 15 22:51:58 volumiobe volumio[1303]: info: [1747342318855] ControllerTidal::prefetch May 15 22:51:58 volumiobe volumio[1303]: info: Getting stream with soundQuality LOSSLESS May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/134870&soundQuality=LOSSLESS" May 15 22:51:58 volumiobe volumio[1303]: info: May 15 22:51:58 volumiobe volumio[1303]: ---------------------------- MPD announces system playlist update May 15 22:51:58 volumiobe volumio[1303]: info: Ignoring MPD Status Update May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/134870&soundQuality=LOSSLESS" took 4 milliseconds May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::setConsumeUpdateService mpd May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand consume 1 May 15 22:51:58 volumiobe volumio[1303]: info: May 15 22:51:58 volumiobe volumio[1303]: ---------------------------- MPD announces system playlist update May 15 22:51:58 volumiobe volumio[1303]: info: Ignoring MPD Status Update May 15 22:51:58 volumiobe volumio[1303]: info: May 15 22:51:58 volumiobe volumio[1303]: ---------------------------- MPD announces system playlist update May 15 22:51:58 volumiobe volumio[1303]: info: Ignoring MPD Status Update May 15 22:51:58 volumiobe volumio[1303]: info: May 15 22:51:58 volumiobe volumio[1303]: ---------------------------- MPD announces system playlist update May 15 22:51:58 volumiobe volumio[1303]: info: Ignoring MPD Status Update May 15 22:51:58 volumiobe volumio[1303]: info: May 15 22:51:58 volumiobe volumio[1303]: ---------------------------- MPD announces state update: options May 15 22:51:58 volumiobe volumio[1303]: info: ------------------------------ 14ms May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand consume 1 took 10 milliseconds May 15 22:51:58 volumiobe volumio[1303]: info: ControllerMpd::getState May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand status May 15 22:51:58 volumiobe volumio[1303]: info: ------------------------------ 10ms May 15 22:51:58 volumiobe volumio[1303]: info: ------------------------------ 8ms May 15 22:51:58 volumiobe volumio[1303]: info: ------------------------------ 7ms May 15 22:51:58 volumiobe volumio[1303]: info: May 15 22:51:58 volumiobe volumio[1303]: ---------------------------- MPD announces state update: options May 15 22:51:58 volumiobe volumio[1303]: info: ControllerMpd::getState May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand status May 15 22:51:58 volumiobe volumio[1303]: info: May 15 22:51:58 volumiobe volumio[1303]: ---------------------------- MPD announces state update: options May 15 22:51:58 volumiobe volumio[1303]: info: ControllerMpd::getState May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand status May 15 22:51:58 volumiobe volumio[1303]: info: May 15 22:51:58 volumiobe volumio[1303]: ---------------------------- MPD announces state update: options May 15 22:51:58 volumiobe volumio[1303]: info: ControllerMpd::getState May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand status May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand status took 12 milliseconds May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand status took 8 milliseconds May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand status took 7 milliseconds May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand status took 4 milliseconds May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::parseState May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::parseState May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::parseState May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::parseState May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand playlistinfo took 5 milliseconds May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand playlistinfo took 6 milliseconds May 15 22:51:58 volumiobe volumio[1303]: info: sendMpdCommand playlistinfo took 5 milliseconds May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::parseTrackInfo May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::parseTrackInfo May 15 22:51:58 volumiobe volumio[1303]: verbose: ControllerMpd::parseTrackInfo May 15 22:51:58 volumiobe volumio[1303]: info: ControllerMpd::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::servicePushState May 15 22:51:58 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 0 May 15 22:51:58 volumiobe volumio[1303]: verbose: STATE SERVICE {"status":"play","position":0,"seek":173245,"duration":198,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"882 Kbps","isStreaming":false,"title":"134869&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/134869&soundQuality=LOSSLESS","trackType":"tidal"} May 15 22:51:58 volumiobe volumio[1303]: verbose: CURRENT POSITION 0 May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::syncState stateService play May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::syncState currentStatus play May 15 22:51:58 volumiobe volumio[1303]: info: Received an update from plugin. extracting info from payload May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:51:58 volumiobe volumio[1303]: info: ControllerMpd::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::servicePushState May 15 22:51:58 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 0 May 15 22:51:58 volumiobe volumio[1303]: verbose: STATE SERVICE {"status":"play","position":0,"seek":173245,"duration":198,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"882 Kbps","isStreaming":false,"title":"134869&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/134869&soundQuality=LOSSLESS","trackType":"tidal"} May 15 22:51:58 volumiobe volumio[1303]: verbose: CURRENT POSITION 0 May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::syncState stateService play May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::syncState currentStatus play May 15 22:51:58 volumiobe volumio[1303]: info: Received an update from plugin. extracting info from payload May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:51:58 volumiobe volumio[1303]: info: ControllerMpd::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::servicePushState May 15 22:51:58 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 0 May 15 22:51:58 volumiobe volumio[1303]: verbose: STATE SERVICE {"status":"play","position":0,"seek":173245,"duration":198,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"882 Kbps","isStreaming":false,"title":"134869&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/134869&soundQuality=LOSSLESS","trackType":"tidal"} May 15 22:51:58 volumiobe volumio[1303]: verbose: CURRENT POSITION 0 May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::syncState stateService play May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::syncState currentStatus play May 15 22:51:58 volumiobe volumio[1303]: info: Received an update from plugin. extracting info from payload May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:51:58 volumiobe volumio[1303]: info: ControllerMpd::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::servicePushState May 15 22:51:58 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 0 May 15 22:51:58 volumiobe volumio[1303]: verbose: STATE SERVICE {"status":"play","position":0,"seek":173245,"duration":198,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"882 Kbps","isStreaming":false,"title":"134869&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/134869&soundQuality=LOSSLESS","trackType":"tidal"} May 15 22:51:58 volumiobe volumio[1303]: verbose: CURRENT POSITION 0 May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::syncState stateService play May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::syncState currentStatus play May 15 22:51:58 volumiobe volumio[1303]: info: Received an update from plugin. extracting info from payload May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:51:58 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:51:59 volumiobe volumio[1303]: info: ------------------------------ 240ms May 15 22:51:59 volumiobe volumio[1303]: info: ------------------------------ 235ms May 15 22:51:59 volumiobe volumio[1303]: info: ------------------------------ 234ms May 15 22:51:59 volumiobe volumio[1303]: info: ------------------------------ 233ms May 15 22:52:03 volumiobe volumio[1303]: info: CoreStateMachine::startPlaybackTimer May 15 22:52:03 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:03 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:03 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:03 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 15 22:52:03 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:11 volumiobe volumio[1303]: info: CoreCommandRouter::volumioGetState May 15 22:52:11 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:11 volumiobe volumio[1303]: Upnp client error: Error: This socket has been ended by the other party May 15 22:52:12 volumiobe volumio[1303]: info: CoreCommandRouter::getUIConfigOnPlugin May 15 22:52:12 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 15 22:52:13 volumiobe volumio[1303]: STREAMING PROXY: Handling url /?data=tidal://song/134870&soundQuality=LOSSLESS May 15 22:52:14 volumiobe volumio[1303]: info: Executing endpoint getStreamUrltidal May 15 22:52:14 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: tidal , getStreamUrlAPI May 15 22:52:14 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 15 22:52:14 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 15 22:52:14 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs May 15 22:52:14 volumiobe volumio[1303]: info: Received Get System Version May 15 22:52:14 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 15 22:52:14 volumiobe volumio[1303]: info: getStreamUrl took 284 milliseconds May 15 22:52:14 volumiobe volumio[1303]: STREAMING PROXY: Got real url: http://sp-pr-cf.audio.tidal.com/mediatracks/CAEaKwgDEicyNjhkMjM1NjBjMzhjZDhlYmNmMDRjMmRhMzczMDg3N182MS5tcDQ/0.flac?Expires=1747345934&Signature=u4zIZdaRuk1pNKwrdhRZhDQls4nl4ihOrn1J8DO20IvXz6UUch0cUkIhhlftGMqMY8s8nrqm1AvgFoL0-HnItb0izqtaGDDYUGgyWEdUC66EMOX8KLrFmNlp2X1u~QIFHrCyPlwdbjenHnnKGwsyTtO6TJGnPWazKQRVdg0VS0T8vdV48o4hgmWYrsroJ9h-nQo-WN275cB7yBn86cF4i9BZpaHd~bTZ37k7hiAxiBKjWg9krfg4btrmB-3dz0kkhg4sF-z8cY9PDEUyZgbrZGOqDloXfkSiCGriO~1myOu1bI1VbBylHLMOHkbirGuP4p~Wp2GFPAiy0twraygq1w__&Key-Pair-Id=K14LZCZ9QUI4JL May 15 22:52:15 volumiobe volumio[1303]: STREAMING PROXY: Response: 200, length: 23880705 May 15 22:52:17 volumiobe volumio[1303]: STREAMING PROXY: Client dropped request, destroying May 15 22:52:17 volumiobe volumio[1303]: info: CoreCommandRouter::volumioGetState May 15 22:52:17 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:25 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 15 22:52:25 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 15 22:52:25 volumiobe volumio[1303]: info: CoreCommandRouter::getUIConfigOnPlugin May 15 22:52:25 volumiobe volumio[1303]: info: CoreCommandRouter::getUIConfigOnPlugin May 15 22:52:25 volumiobe volumio[1303]: Upnp client error: Error: This socket has been ended by the other party May 15 22:52:25 volumiobe volumio[1303]: info: FusionDsp - May 15 22:52:25 volumiobe volumio[1303]: info: FusionDsp - May 15 22:52:25 volumiobe volumio[1303]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 15 22:52:25 volumiobe volumio[1303]: info: FusionDsp - .Bass-FusionDsp.json,.Classic-FusionDsp.json,.Rock-FusionDsp.json,.Soundtrack-FusionDsp.json,.Voice-FusionDsp.json May 15 22:52:25 volumiobe volumio[1303]: info: May 15 22:52:25 volumiobe volumio[1303]: ---------------------------- MPD announces system playlist update May 15 22:52:25 volumiobe volumio[1303]: info: Ignoring MPD Status Update May 15 22:52:25 volumiobe volumio[1303]: info: May 15 22:52:25 volumiobe volumio[1303]: ---------------------------- MPD announces state update: player May 15 22:52:25 volumiobe volumio[1303]: info: ControllerMpd::getState May 15 22:52:25 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand status May 15 22:52:25 volumiobe volumio[1303]: info: May 15 22:52:25 volumiobe volumio[1303]: ---------------------------- MPD announces system playlist update May 15 22:52:25 volumiobe volumio[1303]: info: Ignoring MPD Status Update May 15 22:52:25 volumiobe volumio[1303]: info: May 15 22:52:25 volumiobe volumio[1303]: ---------------------------- MPD announces state update: player May 15 22:52:25 volumiobe volumio[1303]: info: ControllerMpd::getState May 15 22:52:25 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand status May 15 22:52:25 volumiobe volumio[1303]: info: May 15 22:52:25 volumiobe volumio[1303]: ---------------------------- MPD announces system playlist update May 15 22:52:25 volumiobe volumio[1303]: info: Ignoring MPD Status Update May 15 22:52:25 volumiobe volumio[1303]: info: May 15 22:52:25 volumiobe volumio[1303]: ---------------------------- MPD announces state update: player May 15 22:52:25 volumiobe volumio[1303]: info: ControllerMpd::getState May 15 22:52:25 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand status May 15 22:52:25 volumiobe volumio[1303]: info: May 15 22:52:25 volumiobe volumio[1303]: ---------------------------- MPD announces system playlist update May 15 22:52:25 volumiobe volumio[1303]: info: Ignoring MPD Status Update May 15 22:52:25 volumiobe volumio[1303]: info: May 15 22:52:25 volumiobe volumio[1303]: ---------------------------- MPD announces state update: player May 15 22:52:25 volumiobe volumio[1303]: info: ControllerMpd::getState May 15 22:52:25 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand status May 15 22:52:26 volumiobe volumio[1303]: info: ------------------------------ 129ms May 15 22:52:26 volumiobe volumio[1303]: info: sendMpdCommand status took 123 milliseconds May 15 22:52:26 volumiobe volumio[1303]: info: ------------------------------ 120ms May 15 22:52:26 volumiobe volumio[1303]: info: sendMpdCommand status took 117 milliseconds May 15 22:52:26 volumiobe volumio[1303]: info: ------------------------------ 117ms May 15 22:52:26 volumiobe volumio[1303]: info: sendMpdCommand status took 112 milliseconds May 15 22:52:26 volumiobe volumio[1303]: info: ------------------------------ 112ms May 15 22:52:26 volumiobe volumio[1303]: info: sendMpdCommand status took 109 milliseconds May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::parseState May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::parseState May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::parseState May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::parseState May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 15 22:52:26 volumiobe volumio[1303]: info: sendMpdCommand playlistinfo took 12 milliseconds May 15 22:52:26 volumiobe volumio[1303]: info: sendMpdCommand playlistinfo took 12 milliseconds May 15 22:52:26 volumiobe volumio[1303]: info: sendMpdCommand playlistinfo took 11 milliseconds May 15 22:52:26 volumiobe volumio[1303]: info: sendMpdCommand playlistinfo took 11 milliseconds May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::parseTrackInfo May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::parseTrackInfo May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::parseTrackInfo May 15 22:52:26 volumiobe volumio[1303]: verbose: ControllerMpd::parseTrackInfo May 15 22:52:26 volumiobe volumio[1303]: info: ControllerMpd::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::servicePushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: verbose: STATE SERVICE {"status":"play","position":0,"seek":388,"duration":199,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"665 Kbps","isStreaming":false,"title":"134870&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/134870&soundQuality=LOSSLESS","trackType":"tidal"} May 15 22:52:26 volumiobe volumio[1303]: verbose: CURRENT POSITION 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::syncState stateService play May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::syncState currentStatus play May 15 22:52:26 volumiobe volumio[1303]: info: Received an update from plugin. extracting info from payload May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:26 volumiobe volumio[1303]: info: ControllerMpd::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::servicePushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: verbose: STATE SERVICE {"status":"play","position":0,"seek":388,"duration":199,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"721 Kbps","isStreaming":false,"title":"134870&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/134870&soundQuality=LOSSLESS","trackType":"tidal"} May 15 22:52:26 volumiobe volumio[1303]: verbose: CURRENT POSITION 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::syncState stateService play May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::syncState currentStatus play May 15 22:52:26 volumiobe volumio[1303]: info: Received an update from plugin. extracting info from payload May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:26 volumiobe volumio[1303]: info: ControllerMpd::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::servicePushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: verbose: STATE SERVICE {"status":"play","position":0,"seek":388,"duration":199,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"721 Kbps","isStreaming":false,"title":"134870&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/134870&soundQuality=LOSSLESS","trackType":"tidal"} May 15 22:52:26 volumiobe volumio[1303]: verbose: CURRENT POSITION 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::syncState stateService play May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::syncState currentStatus play May 15 22:52:26 volumiobe volumio[1303]: info: Received an update from plugin. extracting info from payload May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:26 volumiobe volumio[1303]: info: ControllerMpd::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::servicePushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: verbose: STATE SERVICE {"status":"play","position":0,"seek":388,"duration":199,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"721 Kbps","isStreaming":false,"title":"134870&soundQuality=LOSSLESS","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/134870&soundQuality=LOSSLESS","trackType":"tidal"} May 15 22:52:26 volumiobe volumio[1303]: verbose: CURRENT POSITION 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::syncState stateService play May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::syncState currentStatus play May 15 22:52:26 volumiobe volumio[1303]: info: Received an update from plugin. extracting info from payload May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:26 volumiobe volumio[1303]: info: CoreStateMachine::pushState May 15 22:52:26 volumiobe volumio[1303]: info: CorePlayQueue::getTrack 1 May 15 22:52:26 volumiobe volumio[1303]: info: CoreCommandRouter::volumioPushState May 15 22:52:26 volumiobe volumio[1303]: info: ------------------------------ 623ms May 15 22:52:26 volumiobe volumio[1303]: info: ------------------------------ 615ms May 15 22:52:26 volumiobe volumio[1303]: info: ------------------------------ 611ms May 15 22:52:26 volumiobe volumio[1303]: info: ------------------------------ 608ms May 15 22:52:27 volumiobe go-librespot[2572]: time="2025-05-15T22:52:27+02:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.65.124:4070: connect: connection timed out" May 15 22:52:27 volumiobe systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 15 22:52:27 volumiobe volumio[1303]: (node:1303) UnhandledPromiseRejectionWarning: Error: socket hang up May 15 22:52:27 volumiobe volumio[1303]: at connResetException (internal/errors.js:607:14) May 15 22:52:27 volumiobe volumio[1303]: at Socket.socketOnEnd (_http_client.js:493:23) May 15 22:52:27 volumiobe volumio[1303]: at Socket.emit (events.js:327:22) May 15 22:52:27 volumiobe volumio[1303]: at endReadableNT (internal/streams/readable.js:1327:12) May 15 22:52:27 volumiobe volumio[1303]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 15 22:52:27 volumiobe volumio[1303]: (node:1303) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2) May 15 22:52:27 volumiobe systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 15 22:52:27 volumiobe volumio[1303]: info: Connection to go-librespot Websocket closed May 15 22:52:29 volumiobe volumio[1303]: info: Starting Uninstall of plugin system_controller - ampswitch May 15 22:52:29 volumiobe volumio[1303]: info: Uninstalling plugin ampswitch May 15 22:52:29 volumiobe volumio[1303]: info: [ASDebug] Port: 4 May 15 22:52:29 volumiobe volumio[1303]: info: [ASDebug] Inverted: false May 15 22:52:29 volumiobe volumio[1303]: info: [ASDebug] Delay: 1 May 15 22:52:31 volumiobe systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 15 22:52:31 volumiobe systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. May 15 22:52:31 volumiobe systemd[1]: Stopped go-librespot Daemon. May 15 22:52:31 volumiobe systemd[1]: Started go-librespot Daemon. May 15 22:52:32 volumiobe volumio[1303]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 15 22:52:36 volumiobe volumio[1303]: TypeError: Cannot read property 'unexport' of undefined May 15 22:52:36 volumiobe volumio[1303]: at AmpSwitchController.freeGPIO (/data/plugins/system_controller/ampswitch/index.js:234:19) May 15 22:52:36 volumiobe volumio[1303]: at AmpSwitchController.onStop (/data/plugins/system_controller/ampswitch/index.js:84:10) May 15 22:52:36 volumiobe volumio[1303]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) May 15 22:52:36 volumiobe volumio[1303]: at PluginManager.unInstallPlugin (/volumio/app/pluginmanager.js:1449:10) May 15 22:52:36 volumiobe volumio[1303]: at CoreCommandRouter.unInstallPlugin (/volumio/app/index.js:1484:22) May 15 22:52:36 volumiobe volumio[1303]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1260:45) May 15 22:52:36 volumiobe volumio[1303]: at Socket.emit (events.js:315:20) May 15 22:52:36 volumiobe volumio[1303]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 May 15 22:52:36 volumiobe volumio[1303]: at processTicksAndRejections (internal/process/task_queues.js:75:11) May 15 22:52:36 volumiobe volumio[1303]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 15 22:52:36 volumiobe go-librespot[3274]: Librespot-go daemon starting... May 15 22:52:36 volumiobe go-librespot[3274]: time="2025-05-15T22:52:36+02:00" level=info msg="generated new device id: c8aca1c75b0557fd4698b838399790788fee9cdf" May 15 22:52:36 volumiobe go-librespot[3274]: time="2025-05-15T22:52:36+02:00" level=debug msg="stored credentials found for 1125112732" May 15 22:52:37 volumiobe go-librespot[3274]: time="2025-05-15T22:52:37+02: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]" May 15 22:52:37 volumiobe go-librespot[3274]: time="2025-05-15T22:52:37+02: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]" May 15 22:52:37 volumiobe go-librespot[3274]: time="2025-05-15T22:52:37+02: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]" May 15 22:52:37 volumiobe go-librespot[3274]: time="2025-05-15T22:52:37+02:00" level=debug msg="zeroconf server listening on port 44263" May 15 22:52:37 volumiobe go-librespot[3274]: time="2025-05-15T22:52:37+02:00" level=debug msg="obtained new client token: AAC4FiUk/244BLeGxlctjQB17dZ0JvRgioZ5qlvnkYzjPSPzwiAfbuW+Jo4tOC1wLR6JjIzdTa/BLPTF2ef5XaVtqk8aW3CdgfafgNIfVFUYaSmh1BBPA65ew8HinEm+Mn6qvcl88PQqh0CJm2xkQ+PPA9bpnG906Ac3rvCFKcEHgpwHxs8Dpvz0pyocph1kGiEvbsuLVCM3YJ8sWe/GD4WJBj5ULksu4s8cSvnc937tfn4S5Fat" May 15 22:52:38 volumiobe sudo[3308]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-15 22:51 May 15 22:52:38 volumiobe sudo[3308]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:47:57 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fddd10196af80fdc784c726185a6abe4"