-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Fri 2025-04-25 13:25:29 CST. -- Apr 25 13:24:00 volumiopi systemd[1]: mpd.service: Succeeded. Apr 25 13:24:00 volumiopi systemd[1]: Stopped Music Player Daemon. Apr 25 13:24:00 volumiopi systemd[1]: Starting Music Player Daemon... Apr 25 13:24:00 volumiopi sudo[3963]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 25 13:24:00 volumiopi sudo[3963]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:24:00 volumiopi sudo[3963]: pam_unix(sudo:session): session closed for user root Apr 25 13:24:02 volumiopi mpd[3966]: Apr 25 13:24 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 25 13:24:02 volumiopi systemd[1]: Started Music Player Daemon. Apr 25 13:24:02 volumiopi mpd_monitor.sh[642]: MPD Monitor Service: MPD restarted due to no mpc output. Apr 25 13:24:02 volumiopi go-librespot[31044]: time="2025-04-25T13:24:02+08:00" level=trace msg="sent dealer ping" Apr 25 13:24:02 volumiopi go-librespot[31044]: time="2025-04-25T13:24:02+08:00" level=trace msg="received dealer pong" Apr 25 13:24:03 volumiopi volumio[1078]: Searching plugin music_service/spop Apr 25 13:24:03 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: spop , search Apr 25 13:24:04 volumiopi volumio[1078]: info: All search sources collected, pushing search results Apr 25 13:24:04 volumiopi volumio[1078]: error: MPD error: The expression evaluated to a falsy value: Apr 25 13:24:04 volumiopi volumio[1078]: assert.ok(self.idling) Apr 25 13:24:04 volumiopi volumio[1078]: error: The expression evaluated to a falsy value: Apr 25 13:24:04 volumiopi volumio[1078]: assert.ok(self.idling) Apr 25 13:24:04 volumiopi volumio[1078]: error: MPD error: The expression evaluated to a falsy value: Apr 25 13:24:04 volumiopi volumio[1078]: assert.ok(self.idling) Apr 25 13:24:04 volumiopi volumio[1078]: error: The expression evaluated to a falsy value: Apr 25 13:24:04 volumiopi volumio[1078]: assert.ok(self.idling) Apr 25 13:24:04 volumiopi volumio[1078]: error: MPD error: The expression evaluated to a falsy value: Apr 25 13:24:04 volumiopi volumio[1078]: assert.ok(self.idling) Apr 25 13:24:04 volumiopi volumio[1078]: error: The expression evaluated to a falsy value: Apr 25 13:24:04 volumiopi volumio[1078]: assert.ok(self.idling) Apr 25 13:24:04 volumiopi volumio[1078]: error: updateQueue error: null Apr 25 13:24:06 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Apr 25 13:24:06 volumiopi volumio[1078]: info: In handleBrowseUri, curUri=spotify:artist:2elBjNSdBE2Y3f0j1mjrql Apr 25 13:24:10 volumiopi volumio[1078]: info: Preload queue cleared Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:56mzU03ZesV0iRroHR2K04 Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:2zjo2j5j3S0Nk21LKCgc8L Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:2g1MHSbgxhcOEKpeWG4pZT Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:4ICIjhyIi03aU3e4gIcSlP Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:6rbZXBUHrCeh1ba03E5uaY Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:39tEWctWn3a4fmocz97cXg Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:6Cf5agUuljOk4nSYZCOtoQ Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:2lIb7a074DL4RLCPAaGdnu Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:3aEb2jEXEBn3HiLLPkj3TP Apr 25 13:24:10 volumiopi volumio[1078]: info: Preloading song: spotify:track:1UdVJoZGkYbJqUXPJnvfHB Apr 25 13:24:10 volumiopi volumio[1078]: info: Preload queue cleared Apr 25 13:24:10 volumiopi volumio[1078]: info: Preload queue cleared Apr 25 13:24:10 volumiopi volumio[1078]: info: No valid Plugin REST Endpoint Apr 25 13:24:13 volumiopi ntpd[837]: Soliciting pool server 198.18.0.18 Apr 25 13:24:15 volumiopi volumio[1078]: info: Preload queue cleared Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::ClearQueue Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::stop Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:15 volumiopi volumio[1078]: info: CorePlayQueue::clearPlayQueue Apr 25 13:24:15 volumiopi volumio[1078]: info: CorePlayQueue::saveQueue Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPushQueue Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::addQueueItems Apr 25 13:24:15 volumiopi volumio[1078]: info: CorePlayQueue::addQueueItems Apr 25 13:24:15 volumiopi volumio[1078]: info: Preload queue cleared Apr 25 13:24:15 volumiopi volumio[1078]: info: Adding Item to queue: spotify:track:56mzU03ZesV0iRroHR2K04 Apr 25 13:24:15 volumiopi volumio[1078]: info: Exploding uri spotify:track:56mzU03ZesV0iRroHR2K04 in service spop Apr 25 13:24:15 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:56mzU03ZesV0iRroHR2K04 Apr 25 13:24:15 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:56mzU03ZesV0iRroHR2K04","service":"spop","name":"擱淺","artist":"Jay Chou","album":"七里香","type":"song","duration":238,"albumart":"https://i.scdn.co/image/ab67616d0000b27300b976d1df4243e5318a7712","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPushQueue Apr 25 13:24:15 volumiopi volumio[1078]: info: CorePlayQueue::saveQueue Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::updateTrackBlock Apr 25 13:24:15 volumiopi volumio[1078]: info: CorePlayQueue::getTrackBlock Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPlay Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::play index 0 Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::stop Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::play index undefined Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:15 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 0 Apr 25 13:24:15 volumiopi volumio[1078]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:24:15 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 0 Apr 25 13:24:15 volumiopi volumio[1078]: info: [1745558655887] ControllerSpotify::clearAddPlayTrack Apr 25 13:24:15 volumiopi volumio[1078]: info: Sending Spotify command with payload to local API: /player/play Apr 25 13:24:16 volumiopi go-librespot[31044]: time="2025-04-25T13:24:16+08:00" level=debug msg="resolved context of track" uri="spotify:track:56mzU03ZesV0iRroHR2K04" Apr 25 13:24:16 volumiopi go-librespot[31044]: time="2025-04-25T13:24:16+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:56mzU03ZesV0iRroHR2K04" Apr 25 13:24:16 volumiopi go-librespot[31044]: time="2025-04-25T13:24:16+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:56mzU03ZesV0iRroHR2K04" Apr 25 13:24:16 volumiopi go-librespot[31044]: time="2025-04-25T13:24:16+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 25 13:24:16 volumiopi go-librespot[31044]: time="2025-04-25T13:24:16+08:00" level=trace msg="emitting websocket event: will_play" Apr 25 13:24:16 volumiopi volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:56mzU03ZesV0iRroHR2K04","play_origin":"go-librespot"}} Apr 25 13:24:16 volumiopi volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:56mzU03ZesV0iRroHR2K04","play_origin":"go-librespot"}} Apr 25 13:24:16 volumiopi go-librespot[31044]: time="2025-04-25T13:24:16+08:00" level=debug msg="selected format OGG_VORBIS_320 (b637f27d5156538833ccd3f23c44cb5af5b97e8d)" uri="spotify:track:56mzU03ZesV0iRroHR2K04" Apr 25 13:24:16 volumiopi go-librespot[31044]: time="2025-04-25T13:24:16+08:00" level=debug msg="requested aes key for file b637f27d5156538833ccd3f23c44cb5af5b97e8d, gid: 56mzU03ZesV0iRroHR2K04" Apr 25 13:24:16 volumiopi go-librespot[31044]: time="2025-04-25T13:24:16+08:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:56mzU03ZesV0iRroHR2K04: failed retrieving audio key: failed retrieving aes key with code 1" Apr 25 13:24:16 volumiopi volumio[1078]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Apr 25 13:24:18 volumiopi ntpd[837]: receive: Unexpected origin timestamp 0xebb59b02.2f2f5486 does not match aorg 0000000000.00000000 from server@198.18.0.10 xmt 0xebb59b02.4cc06564 Apr 25 13:24:22 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Apr 25 13:24:22 volumiopi volumio[1078]: info: In handleBrowseUri, curUri=spotify:album:6sl6IgAnkTvYcta5bOgt4B Apr 25 13:24:23 volumiopi volumio[1078]: info: Preload queue cleared Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:5lh10L81mBNuDtVoxXlcY0 Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:3r2BH563UfH3ZnLxywSe27 Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:0ATZVWuix4MxihrbCnZBfy Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:39tEWctWn3a4fmocz97cXg Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:3g0tcduauR8ju72zhXgCSz Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:0rqkH1SCZaoGhWo0GqrFCM Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:5Omnhld9Y9dDjb7tmyLPYQ Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:4wxyFIwiADGOR81d8pwcvj Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:4dYUjiYWcK8fHq1Gw3Vlx7 Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:1iOBnWtpU48hivRYemWBAl Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:5FTCMO1JDiUuw8RJGnurd8 Apr 25 13:24:23 volumiopi volumio[1078]: info: Preloading song: spotify:track:01BE3X67aMlekmWy5mvRc9 Apr 25 13:24:23 volumiopi volumio[1078]: info: Exploding uri spotify:track:5lh10L81mBNuDtVoxXlcY0 in service spop Apr 25 13:24:23 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:5lh10L81mBNuDtVoxXlcY0 Apr 25 13:24:23 volumiopi volumio[1078]: info: Exploding uri spotify:track:3r2BH563UfH3ZnLxywSe27 in service spop Apr 25 13:24:23 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:3r2BH563UfH3ZnLxywSe27 Apr 25 13:24:23 volumiopi volumio[1078]: info: Exploding uri spotify:track:0ATZVWuix4MxihrbCnZBfy in service spop Apr 25 13:24:23 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:0ATZVWuix4MxihrbCnZBfy Apr 25 13:24:23 volumiopi volumio[1078]: info: Exploding uri spotify:track:39tEWctWn3a4fmocz97cXg in service spop Apr 25 13:24:23 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:39tEWctWn3a4fmocz97cXg Apr 25 13:24:24 volumiopi volumio[1078]: info: Exploding uri spotify:track:3g0tcduauR8ju72zhXgCSz in service spop Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:3g0tcduauR8ju72zhXgCSz Apr 25 13:24:24 volumiopi volumio[1078]: info: Exploding uri spotify:track:0rqkH1SCZaoGhWo0GqrFCM in service spop Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:0rqkH1SCZaoGhWo0GqrFCM Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5lh10L81mBNuDtVoxXlcY0","service":"spop","name":"Intro","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":29,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: info: No valid Plugin REST Endpoint Apr 25 13:24:24 volumiopi volumio[1078]: info: Exploding uri spotify:track:5Omnhld9Y9dDjb7tmyLPYQ in service spop Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:5Omnhld9Y9dDjb7tmyLPYQ Apr 25 13:24:24 volumiopi volumio[1078]: info: Exploding uri spotify:track:4wxyFIwiADGOR81d8pwcvj in service spop Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:4wxyFIwiADGOR81d8pwcvj Apr 25 13:24:24 volumiopi volumio[1078]: info: Exploding uri spotify:track:4dYUjiYWcK8fHq1Gw3Vlx7 in service spop Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:4dYUjiYWcK8fHq1Gw3Vlx7 Apr 25 13:24:24 volumiopi volumio[1078]: info: Exploding uri spotify:track:1iOBnWtpU48hivRYemWBAl in service spop Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:1iOBnWtpU48hivRYemWBAl Apr 25 13:24:24 volumiopi volumio[1078]: info: Exploding uri spotify:track:5FTCMO1JDiUuw8RJGnurd8 in service spop Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:5FTCMO1JDiUuw8RJGnurd8 Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3g0tcduauR8ju72zhXgCSz","service":"spop","name":"紅顏如霜","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":257,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3r2BH563UfH3ZnLxywSe27","service":"spop","name":"最偉大的作品","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":244,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: info: Exploding uri spotify:track:01BE3X67aMlekmWy5mvRc9 in service spop Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:track:01BE3X67aMlekmWy5mvRc9 Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0ATZVWuix4MxihrbCnZBfy","service":"spop","name":"還在流浪","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":265,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:0rqkH1SCZaoGhWo0GqrFCM","service":"spop","name":"不愛我就拉倒","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":246,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:39tEWctWn3a4fmocz97cXg","service":"spop","name":"說好不哭","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":220,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5Omnhld9Y9dDjb7tmyLPYQ","service":"spop","name":"Mojito","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":185,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4wxyFIwiADGOR81d8pwcvj","service":"spop","name":"錯過的煙火","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":257,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:1iOBnWtpU48hivRYemWBAl","service":"spop","name":"粉色海洋","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":186,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:5FTCMO1JDiUuw8RJGnurd8","service":"spop","name":"倒影","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":234,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:01BE3X67aMlekmWy5mvRc9","service":"spop","name":"我是如此相信","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":265,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:24 volumiopi volumio[1078]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:4dYUjiYWcK8fHq1Gw3Vlx7","service":"spop","name":"等你下課","artist":"Jay Chou","album":"最偉大的作品","type":"song","duration":270,"albumart":"https://i.scdn.co/image/ab67616d0000b27320eb9661dbcd873731280b48","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Apr 25 13:24:25 volumiopi volumio[1078]: info: Preload queue cleared Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::ClearQueue Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::stop Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:25 volumiopi volumio[1078]: info: CorePlayQueue::clearPlayQueue Apr 25 13:24:25 volumiopi volumio[1078]: info: CorePlayQueue::saveQueue Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPushQueue Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::addQueueItems Apr 25 13:24:25 volumiopi volumio[1078]: info: CorePlayQueue::addQueueItems Apr 25 13:24:25 volumiopi volumio[1078]: info: Preload queue cleared Apr 25 13:24:25 volumiopi volumio[1078]: info: Adding Item to queue: spotify:album:6sl6IgAnkTvYcta5bOgt4B Apr 25 13:24:25 volumiopi volumio[1078]: info: Exploding uri spotify:album:6sl6IgAnkTvYcta5bOgt4B in service spop Apr 25 13:24:25 volumiopi volumio[1078]: SPOTIFY: EXPLODING URI:spotify:album:6sl6IgAnkTvYcta5bOgt4B Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPushQueue Apr 25 13:24:25 volumiopi volumio[1078]: info: CorePlayQueue::saveQueue Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::updateTrackBlock Apr 25 13:24:25 volumiopi volumio[1078]: info: CorePlayQueue::getTrackBlock Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPlay Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::play index 0 Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::stop Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::play index undefined Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:25 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 0 Apr 25 13:24:25 volumiopi volumio[1078]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:24:25 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 0 Apr 25 13:24:25 volumiopi volumio[1078]: info: [1745558665887] ControllerSpotify::clearAddPlayTrack Apr 25 13:24:25 volumiopi volumio[1078]: info: Sending Spotify command with payload to local API: /player/play Apr 25 13:24:26 volumiopi go-librespot[31044]: time="2025-04-25T13:24:26+08:00" level=debug msg="resolved context of track" uri="spotify:track:5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:26 volumiopi go-librespot[31044]: time="2025-04-25T13:24:26+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:26 volumiopi go-librespot[31044]: time="2025-04-25T13:24:26+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:26 volumiopi go-librespot[31044]: time="2025-04-25T13:24:26+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 25 13:24:26 volumiopi go-librespot[31044]: time="2025-04-25T13:24:26+08:00" level=trace msg="emitting websocket event: will_play" Apr 25 13:24:26 volumiopi volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5lh10L81mBNuDtVoxXlcY0","play_origin":"go-librespot"}} Apr 25 13:24:26 volumiopi volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5lh10L81mBNuDtVoxXlcY0","play_origin":"go-librespot"}} Apr 25 13:24:26 volumiopi go-librespot[31044]: time="2025-04-25T13:24:26+08:00" level=debug msg="selected format OGG_VORBIS_320 (bd685d82c5317bb04929e7a73c2c11ba6277409b)" uri="spotify:track:5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:26 volumiopi go-librespot[31044]: time="2025-04-25T13:24:26+08:00" level=debug msg="requested aes key for file bd685d82c5317bb04929e7a73c2c11ba6277409b, gid: 5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:26 volumiopi go-librespot[31044]: time="2025-04-25T13:24:26+08:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:5lh10L81mBNuDtVoxXlcY0: failed retrieving audio key: failed retrieving aes key with code 1" Apr 25 13:24:26 volumiopi volumio[1078]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Apr 25 13:24:32 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPlay Apr 25 13:24:32 volumiopi volumio[1078]: info: CoreStateMachine::play index undefined Apr 25 13:24:32 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:24:32 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 0 Apr 25 13:24:32 volumiopi volumio[1078]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:24:32 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 0 Apr 25 13:24:32 volumiopi volumio[1078]: info: [1745558672400] ControllerSpotify::clearAddPlayTrack Apr 25 13:24:32 volumiopi volumio[1078]: info: Sending Spotify command with payload to local API: /player/play Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=trace msg="sent dealer ping" Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=debug msg="resolved context of track" uri="spotify:track:5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=trace msg="emitting websocket event: will_play" Apr 25 13:24:32 volumiopi volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5lh10L81mBNuDtVoxXlcY0","play_origin":"go-librespot"}} Apr 25 13:24:32 volumiopi volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5lh10L81mBNuDtVoxXlcY0","play_origin":"go-librespot"}} Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=debug msg="selected format OGG_VORBIS_320 (bd685d82c5317bb04929e7a73c2c11ba6277409b)" uri="spotify:track:5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=debug msg="requested aes key for file bd685d82c5317bb04929e7a73c2c11ba6277409b, gid: 5lh10L81mBNuDtVoxXlcY0" Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=trace msg="received dealer pong" Apr 25 13:24:32 volumiopi go-librespot[31044]: time="2025-04-25T13:24:32+08:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:5lh10L81mBNuDtVoxXlcY0: failed retrieving audio key: failed retrieving aes key with code 1" Apr 25 13:24:32 volumiopi volumio[1078]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Apr 25 13:24:40 volumiopi ntpd[837]: receive: Unexpected origin timestamp 0xebb59b18.2f3963d1 does not match aorg 0000000000.00000000 from server@198.18.0.10 xmt 0xebb59b18.4d169edc Apr 25 13:24:56 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 0 Apr 25 13:24:56 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 1 Apr 25 13:24:56 volumiopi volumio[1078]: info: Prefetching next song Apr 25 13:24:56 volumiopi volumio[1078]: info: [1745558696425] ControllerSpotify::prefetch Apr 25 13:24:56 volumiopi volumio[1078]: info: Sending Spotify command with payload to local API: /player/add_to_queue Apr 25 13:24:56 volumiopi go-librespot[31044]: time="2025-04-25T13:24:56+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 25 13:25:00 volumiopi volumio[1078]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:25:00 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 1 Apr 25 13:25:01 volumiopi volumio[1078]: info: CoreStateMachine::pushState Apr 25 13:25:01 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 1 Apr 25 13:25:01 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 25 13:25:01 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPushState Apr 25 13:25:01 volumiopi volumio[1078]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Apr 25 13:25:01 volumiopi volumio[1078]: info: PeppyMeterBasic ---peppymeterbasic status stop Apr 25 13:25:01 volumiopi volumio[1078]: info: PeppyMeterBasic ---peppymeterbasic status stop Apr 25 13:25:01 volumiopi sudo[4131]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Apr 25 13:25:01 volumiopi sudo[4131]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:25:01 volumiopi sudo[4134]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Apr 25 13:25:01 volumiopi sudo[4131]: pam_unix(sudo:session): session closed for user root Apr 25 13:25:01 volumiopi sudo[4134]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:25:01 volumiopi volumio[1078]: info: peppymeterbasic Daemon Stop Apr 25 13:25:01 volumiopi sudo[4134]: pam_unix(sudo:session): session closed for user root Apr 25 13:25:01 volumiopi volumio[1078]: info: peppymeterbasic Daemon Stop Apr 25 13:25:02 volumiopi go-librespot[31044]: time="2025-04-25T13:25:02+08:00" level=trace msg="sent dealer ping" Apr 25 13:25:02 volumiopi go-librespot[31044]: time="2025-04-25T13:25:02+08:00" level=trace msg="received dealer pong" Apr 25 13:25:04 volumiopi volumio[1078]: info: CoreCommandRouter::volumioPlay Apr 25 13:25:04 volumiopi volumio[1078]: info: CoreStateMachine::play index undefined Apr 25 13:25:04 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:25:04 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 1 Apr 25 13:25:04 volumiopi volumio[1078]: info: CoreStateMachine::startPlaybackTimer Apr 25 13:25:04 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 1 Apr 25 13:25:04 volumiopi volumio[1078]: info: [1745558704327] ControllerSpotify::clearAddPlayTrack Apr 25 13:25:04 volumiopi volumio[1078]: info: Sending Spotify command with payload to local API: /player/play Apr 25 13:25:04 volumiopi go-librespot[31044]: time="2025-04-25T13:25:04+08:00" level=debug msg="resolved context of track" uri="spotify:track:3r2BH563UfH3ZnLxywSe27" Apr 25 13:25:04 volumiopi go-librespot[31044]: time="2025-04-25T13:25:04+08:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3r2BH563UfH3ZnLxywSe27" Apr 25 13:25:04 volumiopi go-librespot[31044]: time="2025-04-25T13:25:04+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3r2BH563UfH3ZnLxywSe27" Apr 25 13:25:04 volumiopi go-librespot[31044]: time="2025-04-25T13:25:04+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 25 13:25:04 volumiopi go-librespot[31044]: time="2025-04-25T13:25:04+08:00" level=trace msg="emitting websocket event: will_play" Apr 25 13:25:04 volumiopi volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3r2BH563UfH3ZnLxywSe27","play_origin":"go-librespot"}} Apr 25 13:25:04 volumiopi volumio[1078]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3r2BH563UfH3ZnLxywSe27","play_origin":"go-librespot"}} Apr 25 13:25:04 volumiopi go-librespot[31044]: time="2025-04-25T13:25:04+08:00" level=debug msg="selected format OGG_VORBIS_320 (4fcbdd6ec82b0e30d160629f4a1cc0f64ccce366)" uri="spotify:track:3r2BH563UfH3ZnLxywSe27" Apr 25 13:25:04 volumiopi go-librespot[31044]: time="2025-04-25T13:25:04+08:00" level=debug msg="requested aes key for file 4fcbdd6ec82b0e30d160629f4a1cc0f64ccce366, gid: 3r2BH563UfH3ZnLxywSe27" Apr 25 13:25:04 volumiopi go-librespot[31044]: time="2025-04-25T13:25:04+08:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3r2BH563UfH3ZnLxywSe27: failed retrieving audio key: failed retrieving aes key with code 1" Apr 25 13:25:04 volumiopi volumio[1078]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Apr 25 13:25:10 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 25 13:25:10 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Apr 25 13:25:17 volumiopi volumio[1078]: info: Stopping peppymeterbasic service Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreStateMachine::stop Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 25 13:25:17 volumiopi volumio[1078]: info: Disabling plugin peppymeterbasic Apr 25 13:25:17 volumiopi volumio[1078]: info: Preparing to generate the ALSA configuration file Apr 25 13:25:17 volumiopi sudo[4156]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Apr 25 13:25:17 volumiopi sudo[4156]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:25:17 volumiopi sudo[4156]: pam_unix(sudo:session): session closed for user root Apr 25 13:25:17 volumiopi volumio[1078]: info: Asound.conf file written Apr 25 13:25:17 volumiopi sudo[4159]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Apr 25 13:25:17 volumiopi sudo[4159]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:25:17 volumiopi sudo[4159]: pam_unix(sudo:session): session closed for user root Apr 25 13:25:17 volumiopi volumio[1078]: No state is present for card vc4hdmi Apr 25 13:25:17 volumiopi volumio[1078]: Found hardware: "vc4-hdmi" "" "" "" "" Apr 25 13:25:17 volumiopi volumio[1078]: Hardware is initialized using a generic method Apr 25 13:25:17 volumiopi volumio[1078]: No state is present for card vc4hdmi Apr 25 13:25:17 volumiopi volumio[1078]: info: Output device has changed, restarting MPD Apr 25 13:25:17 volumiopi sudo[4164]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 25 13:25:17 volumiopi sudo[4164]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:25:17 volumiopi sudo[4164]: pam_unix(sudo:session): session closed for user root Apr 25 13:25:17 volumiopi volumio[1078]: info: Output device has changed, restarting Shairport Sync Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 25 13:25:17 volumiopi sudo[4167]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 25 13:25:17 volumiopi sudo[4167]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:25:17 volumiopi systemd[1]: Stopping Music Player Daemon... Apr 25 13:25:17 volumiopi volumio[1078]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 25 13:25:17 volumiopi volumio[1078]: info: Done. Apr 25 13:25:17 volumiopi systemd[1]: mpd.service: Succeeded. Apr 25 13:25:17 volumiopi systemd[1]: Stopped Music Player Daemon. Apr 25 13:25:17 volumiopi volumio[1078]: info: MPD Permissions set Apr 25 13:25:17 volumiopi volumio[1078]: info: Starting Shairport Sync Apr 25 13:25:17 volumiopi systemd[1]: Starting Music Player Daemon... Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:25:17 volumiopi sudo[4174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 25 13:25:17 volumiopi sudo[4174]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 25 13:25:17 volumiopi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 25 13:25:17 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:25:17 volumiopi systemd[1]: shairport-sync.service: Succeeded. Apr 25 13:25:17 volumiopi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 25 13:25:17 volumiopi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 25 13:25:17 volumiopi sudo[4174]: pam_unix(sudo:session): session closed for user root Apr 25 13:25:17 volumiopi volumio[1078]: info: Shairport-Sync Started Apr 25 13:25:17 volumiopi sudo[4172]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 25 13:25:17 volumiopi sudo[4172]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 25 13:25:17 volumiopi sudo[4172]: pam_unix(sudo:session): session closed for user root Apr 25 13:25:18 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:25:18 volumiopi volumio[1078]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 25 13:25:19 volumiopi mpd[4185]: Apr 25 13:25 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 25 13:25:19 volumiopi systemd[1]: Started Music Player Daemon. Apr 25 13:25:19 volumiopi sudo[4167]: pam_unix(sudo:session): session closed for user root Apr 25 13:25:19 volumiopi volumio[1078]: error: updateQueue error: null Apr 25 13:25:22 volumiopi volumio[1078]: info: Enabling plugin iractivityled Apr 25 13:25:22 volumiopi volumio[1078]: info: Loading plugin "iractivityled"... Apr 25 13:25:23 volumiopi volumio[1078]: info: Applying required configuration parameters for plugin iractivityled Apr 25 13:25:23 volumiopi volumio[1078]: info: [IrActivityLed] Initialized Apr 25 13:25:23 volumiopi volumio[1078]: info: PLUGIN START: iractivityled Apr 25 13:25:23 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 1 of 20 Apr 25 13:25:23 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:23 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 2 of 20 Apr 25 13:25:23 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:23 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 3 of 20 Apr 25 13:25:23 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:24 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 4 of 20 Apr 25 13:25:24 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:24 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 5 of 20 Apr 25 13:25:24 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:24 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 6 of 20 Apr 25 13:25:24 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:25 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 7 of 20 Apr 25 13:25:25 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:25 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 8 of 20 Apr 25 13:25:25 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:25 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 9 of 20 Apr 25 13:25:25 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:26 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 10 of 20 Apr 25 13:25:26 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:26 volumiopi volumio[1078]: info: Enabling plugin ampswitch Apr 25 13:25:26 volumiopi volumio[1078]: info: Loading plugin "ampswitch"... Apr 25 13:25:26 volumiopi ntpd[837]: receive: Unexpected origin timestamp 0xebb59b46.2f3251e7 does not match aorg 0000000000.00000000 from server@198.18.0.10 xmt 0xebb59b46.4e050d80 Apr 25 13:25:27 volumiopi volumio[1078]: info: PLUGIN START: ampswitch Apr 25 13:25:27 volumiopi volumio[1078]: info: Done. Apr 25 13:25:27 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 11 of 20 Apr 25 13:25:27 volumiopi volumio[1078]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 13 Apr 25 13:25:27 volumiopi ntpd[837]: Soliciting pool server 198.18.0.18 Apr 25 13:25:27 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:27 volumiopi volumio[1078]: info: CoreCommandRouter::volumioGetState Apr 25 13:25:27 volumiopi volumio[1078]: info: CorePlayQueue::getTrack 1 Apr 25 13:25:27 volumiopi volumio[1078]: info: [ASDebug] CurState: stop PrevState: na Apr 25 13:25:27 volumiopi volumio[1078]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 25 13:25:27 volumiopi volumio[1078]: info: [ASDebug] CurState: stop PrevState: na Apr 25 13:25:27 volumiopi volumio[1078]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Apr 25 13:25:27 volumiopi volumio[1078]: info: [ASDebug] Port: 24 Apr 25 13:25:27 volumiopi volumio[1078]: info: [ASDebug] Inverted: false Apr 25 13:25:27 volumiopi volumio[1078]: info: [ASDebug] Delay: 720 Apr 25 13:25:27 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 12 of 20 Apr 25 13:25:27 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:27 volumiopi volumio[1078]: info: [IrActivityLed] lirc socket connect: attempt 13 of 20 Apr 25 13:25:27 volumiopi volumio[1078]: info: [IrActivityLed] lircd service is inactive, skipping connection attempt. Error: Command failed: /bin/systemctl is-active lircd Apr 25 13:25:27 volumiopi volumio[1078]: info: [ASDebug] Togle GPIO: OFF Apr 25 13:25:27 volumiopi volumio[1078]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 25 13:25:27 volumiopi volumio[1078]: Error: EBADF: bad file descriptor, write Apr 25 13:25:27 volumiopi volumio[1078]: at Object.writeSync (fs.js:711:3) Apr 25 13:25:27 volumiopi volumio[1078]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8) Apr 25 13:25:27 volumiopi volumio[1078]: at AmpSwitchController.off (/data/plugins/system_controller/ampswitch/index.js:221:23) Apr 25 13:25:27 volumiopi volumio[1078]: at Timeout._onTimeout (/data/plugins/system_controller/ampswitch/index.js:195:88) Apr 25 13:25:27 volumiopi volumio[1078]: at listOnTimeout (internal/timers.js:554:17) Apr 25 13:25:27 volumiopi volumio[1078]: at processTimers (internal/timers.js:497:7) { Apr 25 13:25:27 volumiopi volumio[1078]: errno: -9, Apr 25 13:25:27 volumiopi volumio[1078]: syscall: 'write', Apr 25 13:25:27 volumiopi volumio[1078]: code: 'EBADF' Apr 25 13:25:27 volumiopi volumio[1078]: } Apr 25 13:25:27 volumiopi volumio[1078]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 25 13:25:29 volumiopi sudo[4269]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-25 13:24 Apr 25 13:25:29 volumiopi sudo[4269]: 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="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"