-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sat 2025-01-11 14:55:52 CET. -- Jan 11 14:54:00 volumiogarage systemd[1]: Starting Music Player Daemon... Jan 11 14:54:00 volumiogarage volumio[919]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Jan 11 14:54:01 volumiogarage sudo[1965]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 11 14:54:01 volumiogarage sudo[1965]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 14:54:01 volumiogarage sudo[1965]: pam_unix(sudo:session): session closed for user root Jan 11 14:54:01 volumiogarage volumio[919]: info: Setting Geolocation for MyVolumio to eu7 Jan 11 14:54:01 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:54:01 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:54:01 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:54:01 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 11 14:54:02 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jan 11 14:54:02 volumiogarage volumio[919]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Jan 11 14:54:02 volumiogarage volumio[919]: info: Updating MyVolumio device info Jan 11 14:54:02 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:54:02 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:54:04 volumiogarage volumio[919]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Jan 11 14:54:12 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetVisibleSources Jan 11 14:54:12 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 11 14:54:13 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetState Jan 11 14:54:13 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:13 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jan 11 14:54:13 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 11 14:54:13 volumiogarage volumio[919]: info: Received Get System Info Jan 11 14:54:13 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 11 14:54:13 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 11 14:54:13 volumiogarage volumio[919]: info: Discovery: Getting this device information Jan 11 14:54:13 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetState Jan 11 14:54:13 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:13 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 11 14:54:13 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetState Jan 11 14:54:13 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:19 volumiogarage volumio-remote-updater[555]: [2025-01-11 14:54:19] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] Jan 11 14:54:20 volumiogarage volumio[919]: info: Listing playlists Jan 11 14:54:20 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetState Jan 11 14:54:20 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:20 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 11 14:54:20 volumiogarage volumio[919]: info: Received Get System Info Jan 11 14:54:20 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 11 14:54:20 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 11 14:54:20 volumiogarage volumio[919]: info: Discovery: Getting this device information Jan 11 14:54:20 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetState Jan 11 14:54:20 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:20 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 11 14:54:20 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jan 11 14:54:21 volumiogarage volumio[919]: error: error Jan 11 14:54:21 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jan 11 14:54:22 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 11 14:54:22 volumiogarage volumio[919]: info: Discovery: Disconnected from remote: 172.22.1.13 Jan 11 14:54:22 volumiogarage volumio[919]: info: Discovery: Disconnected from remote: 172.22.1.13 Jan 11 14:54:22 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 11 14:54:22 volumiogarage volumio[919]: info: Received Get System Info Jan 11 14:54:22 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 11 14:54:22 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 11 14:54:22 volumiogarage volumio[919]: info: Discovery: Getting this device information Jan 11 14:54:22 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetState Jan 11 14:54:22 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:22 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 11 14:54:23 volumiogarage volumio[919]: info: Discovery: Connected to remote: 172.22.1.13 Jan 11 14:54:24 volumiogarage volumio-remote-updater[555]: [2025-01-11 14:54:24] [connect] Successful connection Jan 11 14:54:24 volumiogarage volumio[919]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 10 Jan 11 14:54:24 volumiogarage volumio-remote-updater[555]: [2025-01-11 14:54:24] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1736603664 101 Jan 11 14:54:26 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jan 11 14:54:26 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPlay Jan 11 14:54:26 volumiogarage volumio[919]: info: CoreStateMachine::play index undefined Jan 11 14:54:26 volumiogarage volumio[919]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 14:54:26 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:26 volumiogarage volumio[919]: info: CoreStateMachine::startPlaybackTimer Jan 11 14:54:26 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:26 volumiogarage volumio[919]: info: [1736603666918] ControllerWebradio::clearAddPlayTrack Jan 11 14:54:26 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand stop Jan 11 14:54:28 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 11 14:54:28 volumiogarage volumio[919]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jan 11 14:54:28 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jan 11 14:54:28 volumiogarage volumio[919]: info: Received Get System Version Jan 11 14:54:28 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 14:54:28 volumiogarage volumio[919]: info: Received Get System Info Jan 11 14:54:28 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jan 11 14:54:28 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jan 11 14:54:28 volumiogarage volumio[919]: info: Discovery: Getting this device information Jan 11 14:54:28 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetState Jan 11 14:54:28 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:28 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 11 14:54:29 volumiogarage mpd[1980]: Jan 11 14:54 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 11 14:54:29 volumiogarage volumio[919]: error: updateQueue error: null Jan 11 14:54:29 volumiogarage volumio[919]: info: sendMpdCommand stop took 2321 milliseconds Jan 11 14:54:29 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand clear Jan 11 14:54:29 volumiogarage volumio[919]: info: Jan 11 14:54:29 volumiogarage volumio[919]: ---------------------------- MPD announces system playlist update Jan 11 14:54:29 volumiogarage volumio[919]: info: Ignoring MPD Status Update Jan 11 14:54:29 volumiogarage volumio[919]: info: sendMpdCommand clear took 2 milliseconds Jan 11 14:54:29 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand load "https://streams.egofm.de/egoFM-hq?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzOTI5OTM3NiwiaXNzIjoidGlzcnYifQ.cGAEtKj27inJz0pbVj7r49ahM089XLWtgXUF6TT-Pe8" Jan 11 14:54:29 volumiogarage volumio[919]: error: updateQueue error: null Jan 11 14:54:29 volumiogarage volumio[919]: info: ------------------------------ 4ms Jan 11 14:54:29 volumiogarage systemd[1]: Started Music Player Daemon. Jan 11 14:54:29 volumiogarage go-librespot[1245]: time="2025-01-11T14:54:29+01:00" level=error msg="did not receive last pong from dealer, 30s passed" Jan 11 14:54:30 volumiogarage go-librespot[1245]: time="2025-01-11T14:54:30+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusServiceRestart and reason = \"\"" Jan 11 14:54:30 volumiogarage mpd_monitor.sh[556]: MPD restarted due to no mpc output. Jan 11 14:54:30 volumiogarage go-librespot[1245]: time="2025-01-11T14:54:30+01:00" level=debug msg="re-established dealer connection" Jan 11 14:54:30 volumiogarage go-librespot[1245]: time="2025-01-11T14:54:30+01:00" level=debug msg="received connection id: ZWM4OGY0ZTUtNGIzNS00NmIzLWI1MTAtMzA5MTE3YThhZGY0K2RlYWxlcit0Y3A6Ly8wYWNiZDlhZC5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArOUNEMkJFQUZFMUI1OEFFRjQzRjEwMkUwQjkwNDQ1OEFBNDA3MEIzQUFGRjA0OTVEODAzOEUyMjI4QjQzNjYxRg==" Jan 11 14:54:31 volumiogarage go-librespot[1245]: time="2025-01-11T14:54:31+01:00" level=debug msg="put connect state because NEW_DEVICE" Jan 11 14:54:34 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand add "https://streams.egofm.de/egoFM-hq?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzOTI5OTM3NiwiaXNzIjoidGlzcnYifQ.cGAEtKj27inJz0pbVj7r49ahM089XLWtgXUF6TT-Pe8" Jan 11 14:54:34 volumiogarage volumio[919]: info: Jan 11 14:54:34 volumiogarage volumio[919]: ---------------------------- MPD announces system playlist update Jan 11 14:54:34 volumiogarage volumio[919]: info: Ignoring MPD Status Update Jan 11 14:54:34 volumiogarage volumio[919]: info: sendMpdCommand add "https://streams.egofm.de/egoFM-hq?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzOTI5OTM3NiwiaXNzIjoidGlzcnYifQ.cGAEtKj27inJz0pbVj7r49ahM089XLWtgXUF6TT-Pe8" took 2 milliseconds Jan 11 14:54:34 volumiogarage volumio[919]: info: CoreStateMachine::setConsumeUpdateService mpd Jan 11 14:54:34 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand play Jan 11 14:54:34 volumiogarage volumio[919]: info: ------------------------------ 60ms Jan 11 14:54:34 volumiogarage volumio[919]: info: sendMpdCommand play took 51 milliseconds Jan 11 14:54:37 volumiogarage volumio[919]: info: Jan 11 14:54:37 volumiogarage volumio[919]: ---------------------------- MPD announces state update: player Jan 11 14:54:37 volumiogarage volumio[919]: info: ControllerMpd::getState Jan 11 14:54:37 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand status Jan 11 14:54:38 volumiogarage kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Jan 11 14:54:38 volumiogarage volumio[919]: info: sendMpdCommand status took 182 milliseconds Jan 11 14:54:38 volumiogarage volumio[919]: verbose: ControllerMpd::parseState Jan 11 14:54:38 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 14:54:38 volumiogarage volumio[919]: info: Jan 11 14:54:38 volumiogarage volumio[919]: ---------------------------- MPD announces system playlist update Jan 11 14:54:38 volumiogarage volumio[919]: info: Ignoring MPD Status Update Jan 11 14:54:38 volumiogarage volumio[919]: info: Jan 11 14:54:38 volumiogarage volumio[919]: ---------------------------- MPD announces state update: player Jan 11 14:54:38 volumiogarage volumio[919]: info: ControllerMpd::getState Jan 11 14:54:38 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand status Jan 11 14:54:38 volumiogarage volumio[919]: info: sendMpdCommand playlistinfo took 18 milliseconds Jan 11 14:54:38 volumiogarage volumio[919]: verbose: ControllerMpd::parseTrackInfo Jan 11 14:54:38 volumiogarage volumio[919]: info: ControllerMpd::pushState Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreCommandRouter::servicePushState Jan 11 14:54:38 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:38 volumiogarage volumio[919]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Monophonics - Last One Standing","artist":"egoFM - Musik wie nirgendwo sonst","album":null,"uri":"https://streams.egofm.de/egoFM-hq?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzOTI5OTM3NiwiaXNzIjoidGlzcnYifQ.cGAEtKj27inJz0pbVj7r49ahM089XLWtgXUF6TT-Pe8","trackType":""} Jan 11 14:54:38 volumiogarage volumio[919]: verbose: CURRENT POSITION 0 Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreStateMachine::syncState stateService play Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreStateMachine::syncState currentStatus stop Jan 11 14:54:38 volumiogarage volumio[919]: info: ------------------------------ 286ms Jan 11 14:54:38 volumiogarage volumio[919]: info: ------------------------------ 77ms Jan 11 14:54:38 volumiogarage volumio[919]: info: sendMpdCommand status took 77 milliseconds Jan 11 14:54:38 volumiogarage volumio[919]: verbose: ControllerMpd::parseState Jan 11 14:54:38 volumiogarage volumio[919]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 14:54:38 volumiogarage volumio[919]: info: sendMpdCommand playlistinfo took 2 milliseconds Jan 11 14:54:38 volumiogarage volumio[919]: verbose: ControllerMpd::parseTrackInfo Jan 11 14:54:38 volumiogarage volumio[919]: info: ControllerMpd::pushState Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreCommandRouter::servicePushState Jan 11 14:54:38 volumiogarage volumio[919]: info: CorePlayQueue::getTrack 0 Jan 11 14:54:38 volumiogarage volumio[919]: verbose: STATE SERVICE {"status":"play","position":0,"seek":880,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Monophonics - Last One Standing","artist":"egoFM - Musik wie nirgendwo sonst","album":null,"uri":"https://streams.egofm.de/egoFM-hq?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzOTI5OTM3NiwiaXNzIjoidGlzcnYifQ.cGAEtKj27inJz0pbVj7r49ahM089XLWtgXUF6TT-Pe8","trackType":""} Jan 11 14:54:38 volumiogarage volumio[919]: verbose: CURRENT POSITION 0 Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreStateMachine::syncState stateService play Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreStateMachine::syncState currentStatus play Jan 11 14:54:38 volumiogarage volumio[919]: info: Received an update from plugin. extracting info from payload Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreStateMachine::pushState Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPushState Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreStateMachine::pushState Jan 11 14:54:38 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPushState Jan 11 14:54:38 volumiogarage volumio[919]: info: ------------------------------ 161ms Jan 11 14:54:38 volumiogarage volumio[919]: info: [GPIO_Control] Status changed: play Jan 11 14:54:38 volumiogarage volumio[919]: info: [GPIO_Control] Handling event: musicPlay Jan 11 14:54:38 volumiogarage volumio[919]: info: [GPIO_Control] Status changed: play Jan 11 14:54:38 volumiogarage volumio[919]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 11 14:54:38 volumiogarage volumio[919]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 11 14:54:55 volumiogarage volumio[919]: info: VolumeController::SetAlsaVolume29 Jan 11 14:54:55 volumiogarage volumio[919]: info: CoreStateMachine::pushState Jan 11 14:54:55 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:54:55 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPushState Jan 11 14:54:55 volumiogarage volumio[919]: info: [GPIO_Control] Status changed: play Jan 11 14:54:55 volumiogarage volumio[919]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29 Jan 11 14:54:55 volumiogarage volumio[919]: SPOTIFY: SPOTIFY VOLUME 40 Jan 11 14:54:55 volumiogarage volumio[919]: SPOTIFY: VOLUMIO VOLUME 29 Jan 11 14:54:55 volumiogarage volumio[919]: SPOTIFY: DELTA VOLUME ENOUGH: true Jan 11 14:54:55 volumiogarage volumio[919]: info: Setting Spotify Volume from Volumio: 29 Jan 11 14:54:56 volumiogarage volumio[919]: SPOTIFY: SETTING SPOTIFY VOLUME 29 Jan 11 14:54:56 volumiogarage volumio[919]: info: Sending Spotify command with payload to local API: /player/volume Jan 11 14:54:56 volumiogarage go-librespot[1245]: time="2025-01-11T14:54:56+01:00" level=debug msg="update volume to 19005/65535" Jan 11 14:54:56 volumiogarage go-librespot[1245]: time="2025-01-11T14:54:56+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Jan 11 14:54:57 volumiogarage go-librespot[1245]: time="2025-01-11T14:54:56+01:00" level=trace msg="emitting websocket event: volume" Jan 11 14:54:57 volumiogarage volumio[919]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Jan 11 14:54:57 volumiogarage volumio[919]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Jan 11 14:54:57 volumiogarage volumio[919]: info: VolumeController::SetAlsaVolume25 Jan 11 14:54:58 volumiogarage volumio[919]: info: CoreStateMachine::pushState Jan 11 14:54:58 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:54:58 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPushState Jan 11 14:54:58 volumiogarage volumio[919]: info: [GPIO_Control] Status changed: play Jan 11 14:55:02 volumiogarage volumio[919]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25 Jan 11 14:55:02 volumiogarage volumio[919]: SPOTIFY: SPOTIFY VOLUME 29 Jan 11 14:55:02 volumiogarage volumio[919]: SPOTIFY: VOLUMIO VOLUME 25 Jan 11 14:55:02 volumiogarage volumio[919]: SPOTIFY: DELTA VOLUME ENOUGH: true Jan 11 14:55:02 volumiogarage volumio[919]: info: Setting Spotify Volume from Volumio: 25 Jan 11 14:55:03 volumiogarage volumio[919]: info: VolumeController::SetAlsaVolume52 Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreStateMachine::pushState Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPushState Jan 11 14:55:03 volumiogarage volumio[919]: info: VolumeController::SetAlsaVolume85 Jan 11 14:55:03 volumiogarage volumio[919]: info: VolumeController::SetAlsaVolume35 Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreStateMachine::pushState Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPushState Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreStateMachine::pushState Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPushState Jan 11 14:55:03 volumiogarage volumio[919]: info: [GPIO_Control] Status changed: play Jan 11 14:55:03 volumiogarage volumio[919]: info: [GPIO_Control] Status changed: play Jan 11 14:55:03 volumiogarage volumio[919]: info: [GPIO_Control] Status changed: play Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: SPOTIFY VOLUME 25 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: VOLUMIO VOLUME 52 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: DELTA VOLUME ENOUGH: true Jan 11 14:55:03 volumiogarage volumio[919]: info: Setting Spotify Volume from Volumio: 52 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: SPOTIFY VOLUME 52 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: VOLUMIO VOLUME 35 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: DELTA VOLUME ENOUGH: true Jan 11 14:55:03 volumiogarage volumio[919]: info: Setting Spotify Volume from Volumio: 35 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Jan 11 14:55:03 volumiogarage volumio[919]: info: VolumeController::SetAlsaVolume51 Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreStateMachine::pushState Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 14:55:03 volumiogarage volumio[919]: info: CoreCommandRouter::volumioPushState Jan 11 14:55:03 volumiogarage volumio[919]: info: [GPIO_Control] Status changed: play Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: SPOTIFY VOLUME 35 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: VOLUMIO VOLUME 51 Jan 11 14:55:03 volumiogarage volumio[919]: SPOTIFY: DELTA VOLUME ENOUGH: true Jan 11 14:55:03 volumiogarage volumio[919]: info: Setting Spotify Volume from Volumio: 51 Jan 11 14:55:05 volumiogarage volumio[919]: SPOTIFY: SETTING SPOTIFY VOLUME 51 Jan 11 14:55:05 volumiogarage volumio[919]: info: Sending Spotify command with payload to local API: /player/volume Jan 11 14:55:05 volumiogarage go-librespot[1245]: time="2025-01-11T14:55:05+01:00" level=debug msg="update volume to 33422/65535" Jan 11 14:55:05 volumiogarage go-librespot[1245]: time="2025-01-11T14:55:05+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Jan 11 14:55:05 volumiogarage go-librespot[1245]: time="2025-01-11T14:55:05+01:00" level=trace msg="emitting websocket event: volume" Jan 11 14:55:05 volumiogarage volumio[919]: SPOTIFY: received: {"type":"volume","data":{"value":51,"max":100}} Jan 11 14:55:05 volumiogarage volumio[919]: SPOTIFY: RECEIVED SPOTIFY VOLUME 51 Jan 11 14:55:07 volumiogarage volumio[919]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 11 14:55:08 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jan 11 14:55:09 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jan 11 14:55:09 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jan 11 14:55:10 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Jan 11 14:55:11 volumiogarage volumio[919]: info: CoreCommandRouter::volumioGetState Jan 11 14:55:16 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jan 11 14:55:16 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Jan 11 14:55:18 volumiogarage volumio[919]: error: Failed to check for new versions for plugin YouTube Music: Error: Invalid argument not valid semver ('' received) Jan 11 14:55:31 volumiogarage volumio[919]: info: Enabling plugin fusiondsp Jan 11 14:55:31 volumiogarage volumio[919]: info: Loading plugin "fusiondsp"... Jan 11 14:55:33 volumiogarage volumio[919]: info: Preparing to generate the ALSA configuration file Jan 11 14:55:33 volumiogarage volumio[919]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jan 11 14:55:33 volumiogarage volumio[919]: info: Reading ALSA contributions from plugins. Jan 11 14:55:33 volumiogarage volumio[919]: info: Asound.conf file unchanged, so no further update is needed Jan 11 14:55:33 volumiogarage volumio[919]: info: Output device has changed, restarting MPD Jan 11 14:55:33 volumiogarage volumio[919]: info: Output device has changed, restarting Shairport Sync Jan 11 14:55:33 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:55:33 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:55:33 volumiogarage sudo[2232]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 11 14:55:33 volumiogarage sudo[2230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 11 14:55:33 volumiogarage sudo[2232]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 14:55:33 volumiogarage sudo[2230]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 14:55:33 volumiogarage sudo[2230]: pam_unix(sudo:session): session closed for user root Jan 11 14:55:34 volumiogarage volumio[919]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 11 14:55:34 volumiogarage volumio[919]: info: PLUGIN START: fusiondsp Jan 11 14:55:34 volumiogarage volumio[919]: info: Loading i18n strings for locale de Jan 11 14:55:34 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 11 14:55:34 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:55:34 volumiogarage volumio[919]: info: FusionDsp - mixtype--------------------- Hardware Jan 11 14:55:34 volumiogarage volumio[919]: info: Preparing to generate the ALSA configuration file Jan 11 14:55:34 volumiogarage volumio[919]: info: Done. Jan 11 14:55:34 volumiogarage volumio[919]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jan 11 14:55:34 volumiogarage volumio[919]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Jan 11 14:55:34 volumiogarage volumio[919]: info: Reading ALSA contributions from plugins. Jan 11 14:55:34 volumiogarage volumio[919]: info: MPD Permissions set Jan 11 14:55:34 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:55:34 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:55:34 volumiogarage systemd[1]: Stopping Music Player Daemon... Jan 11 14:55:34 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:55:34 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 14:55:34 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:55:34 volumiogarage volumio[919]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 11 14:55:34 volumiogarage volumio[919]: info: Starting Shairport Sync Jan 11 14:55:39 volumiogarage volumio[919]: info: camilladsp spawned new process with pid undefined, instance 1, run: true Jan 11 14:55:39 volumiogarage volumio[919]: info: camilladsp service started and running in background, instance 1 Jan 11 14:55:39 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 14:55:39 volumiogarage sudo[2261]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 11 14:55:39 volumiogarage sudo[2261]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 14:55:40 volumiogarage sudo[2273]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Jan 11 14:55:40 volumiogarage volumio[919]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Jan 11 14:55:40 volumiogarage volumio[919]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json Jan 11 14:55:40 volumiogarage volumio[919]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Jan 11 14:55:40 volumiogarage volumio[919]: info: FusionDsp loaded Jan 11 14:55:40 volumiogarage volumio[919]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jan 11 14:55:40 volumiogarage sudo[2273]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 11 14:55:40 volumiogarage volumio[919]: info: FusionDsp - Reporting Fusion DSP Enabled Jan 11 14:55:40 volumiogarage volumio[919]: info: Adding Signal Path Element [object Object] Jan 11 14:55:40 volumiogarage volumio[919]: info: Adding fusiondspeq DSP Signal Path Element Jan 11 14:55:41 volumiogarage sudo[2273]: pam_unix(sudo:session): session closed for user root Jan 11 14:55:41 volumiogarage systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jan 11 14:55:41 volumiogarage volumio[919]: info: FusionDsp - ---- installed callbackRead Jan 11 14:55:41 volumiogarage volumio[919]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:55:41 volumiogarage volumio[919]: Error: spawn /data/plugins/audio_interface/fusiondsp/camilladsp ENOENT Jan 11 14:55:41 volumiogarage volumio[919]: at Process.ChildProcess._handle.onexit (internal/child_process.js:269:19) Jan 11 14:55:41 volumiogarage volumio[919]: at onErrorNT (internal/child_process.js:465:16) Jan 11 14:55:41 volumiogarage volumio[919]: at processTicksAndRejections (internal/process/task_queues.js:80:21) { Jan 11 14:55:41 volumiogarage volumio[919]: errno: -2, Jan 11 14:55:41 volumiogarage volumio[919]: code: 'ENOENT', Jan 11 14:55:41 volumiogarage volumio[919]: syscall: 'spawn /data/plugins/audio_interface/fusiondsp/camilladsp', Jan 11 14:55:41 volumiogarage volumio[919]: path: '/data/plugins/audio_interface/fusiondsp/camilladsp', Jan 11 14:55:41 volumiogarage volumio[919]: spawnargs: [ Jan 11 14:55:41 volumiogarage volumio[919]: '-p', Jan 11 14:55:41 volumiogarage volumio[919]: 9876, Jan 11 14:55:41 volumiogarage volumio[919]: '-o', Jan 11 14:55:41 volumiogarage volumio[919]: '/tmp/camilladsp.log', Jan 11 14:55:41 volumiogarage volumio[919]: '-l', Jan 11 14:55:41 volumiogarage volumio[919]: 'warn', Jan 11 14:55:41 volumiogarage volumio[919]: '/data/configuration/audio_interface/fusiondsp/camilladsp.yml' Jan 11 14:55:41 volumiogarage volumio[919]: ] Jan 11 14:55:41 volumiogarage volumio[919]: } Jan 11 14:55:41 volumiogarage volumio[919]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 14:55:43 volumiogarage systemd[1]: shairport-sync.service: Succeeded. Jan 11 14:55:43 volumiogarage systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jan 11 14:55:43 volumiogarage systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jan 11 14:55:43 volumiogarage sudo[2261]: pam_unix(sudo:session): session closed for user root Jan 11 14:55:46 volumiogarage volumio-remote-updater[555]: [2025-01-11 14:55:46] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] Jan 11 14:55:51 volumiogarage volumio-remote-updater[555]: [2025-01-11 14:55:51] [connect] Successful connection Jan 11 14:55:52 volumiogarage sudo[2305]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-11 14:54 Jan 11 14:55:52 volumiogarage sudo[2305]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"