-- Logs begin at Thu 2019-02-14 10:11:58 UTC, end at Tue 2025-11-04 15:51:38 UTC. -- Nov 04 15:50:06 volumio go-librespot[1267]: time="2025-11-04T15:50:06Z" level=debug msg="fetched chunk 21/22, size: 524288" uri="spotify:track:73TxYZd0lBCVRrHawrAglA" Nov 04 15:50:09 volumio volumio[975]: info: CoreCommandRouter::volumioPrevious Nov 04 15:50:09 volumio volumio[975]: info: Spotify previous Nov 04 15:50:09 volumio volumio[975]: info: Sending Spotify command to local API: /player/prev Nov 04 15:50:09 volumio go-librespot[1267]: time="2025-11-04T15:50:09Z" level=debug msg="seek track to 0ms" Nov 04 15:50:09 volumio go-librespot[1267]: time="2025-11-04T15:50:09Z" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:73TxYZd0lBCVRrHawrAglA" Nov 04 15:50:09 volumio go-librespot[1267]: time="2025-11-04T15:50:09Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 04 15:50:09 volumio go-librespot[1267]: time="2025-11-04T15:50:09Z" level=trace msg="scheduling prefetch in 244s" Nov 04 15:50:09 volumio go-librespot[1267]: time="2025-11-04T15:50:09Z" level=trace msg="emitting websocket event: seek" Nov 04 15:50:09 volumio volumio[975]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:73TxYZd0lBCVRrHawrAglA","position":0,"duration":274088,"play_origin":"playlist"}} Nov 04 15:50:09 volumio volumio[975]: SPOTIFY: PUSH STATE SPOTIFY Nov 04 15:50:09 volumio volumio[975]: SPOTIFY: {"status":"play","service":"spop","title":"Sweet Emotion","artist":"Aerosmith","album":"Toys In The Attic","albumart":"https://i.scdn.co/image/ab67616d00001e028cffbbb7fe8645a486a85ea9","uri":"spotify:track:73TxYZd0lBCVRrHawrAglA","trackType":"spotify","seek":0,"duration":274,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Nov 04 15:50:09 volumio volumio[975]: info: CoreCommandRouter::servicePushState Nov 04 15:50:09 volumio volumio[975]: info: CoreStateMachine::pushState Nov 04 15:50:09 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 04 15:50:09 volumio volumio[975]: info: CoreCommandRouter::volumioPushState Nov 04 15:50:09 volumio volumio[975]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 04 15:50:16 volumio volumio[975]: info: CoreCommandRouter::volumioGetVisibleSources Nov 04 15:50:16 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 04 15:50:16 volumio volumio[975]: info: CoreCommandRouter::volumioGetQueue Nov 04 15:50:16 volumio volumio[975]: info: CoreStateMachine::getQueue Nov 04 15:50:16 volumio volumio[975]: info: CorePlayQueue::getQueue Nov 04 15:50:21 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 04 15:50:21 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 04 15:50:21 volumio volumio[975]: info: Discovery: Getting this device information Nov 04 15:50:21 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Nov 04 15:50:21 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 04 15:50:23 volumio go-librespot[1267]: time="2025-11-04T15:50:23Z" level=trace msg="sent dealer ping" Nov 04 15:50:23 volumio go-librespot[1267]: time="2025-11-04T15:50:23Z" level=trace msg="received dealer pong" Nov 04 15:50:27 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 04 15:50:27 volumio volumio[975]: info: Received Get System Info Nov 04 15:50:27 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 04 15:50:27 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 04 15:50:27 volumio volumio[975]: info: Discovery: Getting this device information Nov 04 15:50:27 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Nov 04 15:50:27 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Nov 04 15:50:30 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Nov 04 15:50:41 volumio volumio[975]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Nov 04 15:50:41 volumio volumio[975]: info: Preparing to save Alsa Options, stopping services first Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::volumioPause Nov 04 15:50:41 volumio volumio[975]: info: CoreStateMachine::pause Nov 04 15:50:41 volumio volumio[975]: info: CoreStateMachine::stPlaybackTimer Nov 04 15:50:41 volumio volumio[975]: info: CoreStateMachine::servicePause Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::servicePause Nov 04 15:50:41 volumio volumio[975]: info: Spotify Received pause Nov 04 15:50:41 volumio volumio[975]: SPOTIFY: SPOTIFY PAUSE Nov 04 15:50:41 volumio volumio[975]: SPOTIFY: {"status":"play","title":"Sweet Emotion","artist":"Aerosmith","album":"Toys In The Attic","albumart":"https://i.scdn.co/image/ab67616d00001e028cffbbb7fe8645a486a85ea9","uri":"spotify:track:73TxYZd0lBCVRrHawrAglA","trackType":"spotify","codec":"ogg","seek":0,"duration":274,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Nov 04 15:50:41 volumio volumio[975]: info: Sending Spotify command to local API: /player/pause Nov 04 15:50:41 volumio volumio[975]: info: Saving Audio Output to: {"output_device":{"value":"0","label":"HDMI Out"},"i2s":false,"i2sid":{"value":"adafruit-max98357","label":"Adafruit MAX98357"}} Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 04 15:50:41 volumio volumio[975]: info: Enabling PI HDMI Output Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 04 15:50:41 volumio volumio[975]: info: Found match in Cards Database: setting mixer PCM for card HDMI Out Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::volumioUpdateVolumeSettings Nov 04 15:50:41 volumio volumio[975]: info: Updating Volume Controller Parameters: Device: 0 Name: HDMI Out Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Nov 04 15:50:41 volumio volumio[975]: info: Disabling external Volume Control Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 04 15:50:41 volumio volumio[975]: info: Preparing to generate the ALSA configuration file Nov 04 15:50:41 volumio go-librespot[1267]: time="2025-11-04T15:50:41Z" level=debug msg="pause track at 32257ms" Nov 04 15:50:41 volumio volumio[975]: info: Raspberry PI HDMI Output Enabled Nov 04 15:50:41 volumio volumio[975]: info: VolumeController:: Volume=86 Mute =false Nov 04 15:50:41 volumio volumio[975]: info: CoreStateMachine::pushState Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 04 15:50:41 volumio volumio[975]: info: CoreCommandRouter::volumioPushState Nov 04 15:50:41 volumio sudo[3928]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl store Nov 04 15:50:41 volumio sudo[3928]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:41 volumio go-librespot[1267]: time="2025-11-04T15:50:41Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 04 15:50:42 volumio sudo[3928]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 04 15:50:42 volumio go-librespot[1267]: time="2025-11-04T15:50:42Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 04 15:50:42 volumio go-librespot[1267]: time="2025-11-04T15:50:42Z" level=trace msg="emitting websocket event: paused" Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Nov 04 15:50:42 volumio volumio[975]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Nov 04 15:50:42 volumio volumio[975]: SPOTIFY: SPOTIFY VOLUME 100 Nov 04 15:50:42 volumio volumio[975]: SPOTIFY: VOLUMIO VOLUME 86 Nov 04 15:50:42 volumio volumio[975]: SPOTIFY: DELTA VOLUME ENOUGH: true Nov 04 15:50:42 volumio volumio[975]: info: Setting Spotify Volume from Volumio: 86 Nov 04 15:50:42 volumio volumio[975]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:73TxYZd0lBCVRrHawrAglA","play_origin":"playlist"}} Nov 04 15:50:42 volumio volumio[975]: SPOTIFY: PUSH STATE SPOTIFY Nov 04 15:50:42 volumio volumio[975]: SPOTIFY: {"status":"pause","service":"spop","title":"Sweet Emotion","artist":"Aerosmith","album":"Toys In The Attic","albumart":"https://i.scdn.co/image/ab67616d00001e028cffbbb7fe8645a486a85ea9","uri":"spotify:track:73TxYZd0lBCVRrHawrAglA","trackType":"spotify","seek":32000,"duration":274,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::servicePushState Nov 04 15:50:42 volumio volumio[975]: info: CoreStateMachine::pushState Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::volumioPushState Nov 04 15:50:42 volumio volumio[975]: info: Alsa Settings successfully stored Nov 04 15:50:42 volumio volumio[975]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Nov 04 15:50:42 volumio volumio[975]: info: Asound.conf file written Nov 04 15:50:42 volumio sudo[3937]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Nov 04 15:50:42 volumio sudo[3937]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:42 volumio sudo[3937]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:42 volumio volumio[975]: info: Output device has changed, restarting MPD Nov 04 15:50:42 volumio sudo[3942]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 04 15:50:42 volumio sudo[3942]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:42 volumio volumio[975]: info: Output device has changed, restarting Shairport Sync Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 04 15:50:42 volumio sudo[3942]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:42 volumio sudo[3945]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 04 15:50:42 volumio sudo[3945]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:42 volumio systemd[1]: Stopping Music Player Daemon... Nov 04 15:50:42 volumio volumio[975]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 04 15:50:42 volumio volumio[975]: info: Output device has changed, restarting MPD Nov 04 15:50:42 volumio systemd[1]: mpd.service: Succeeded. Nov 04 15:50:42 volumio systemd[1]: Stopped Music Player Daemon. Nov 04 15:50:42 volumio sudo[3952]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 04 15:50:42 volumio sudo[3952]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:42 volumio systemd[1]: Starting Music Player Daemon... Nov 04 15:50:42 volumio volumio[975]: info: Output device has changed, restarting Shairport Sync Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 04 15:50:42 volumio sudo[3952]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:42 volumio sudo[3954]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 04 15:50:42 volumio sudo[3954]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:42 volumio volumio[975]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 04 15:50:42 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Nov 04 15:50:42 volumio systemd[1]: mpd.service: Succeeded. Nov 04 15:50:42 volumio volumio[975]: info: MPD Permissions set Nov 04 15:50:42 volumio volumio[975]: info: MPD Permissions set Nov 04 15:50:42 volumio systemd[1]: Stopped Music Player Daemon. Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio systemd[1]: Starting Music Player Daemon... Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 04 15:50:42 volumio volumio[975]: info: Starting Shairport Sync Nov 04 15:50:42 volumio volumio[975]: info: Starting Shairport Sync Nov 04 15:50:42 volumio sudo[3960]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 04 15:50:42 volumio sudo[3960]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:42 volumio sudo[3970]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 04 15:50:42 volumio sudo[3960]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:42 volumio sudo[3970]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:42 volumio sudo[3973]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 04 15:50:42 volumio sudo[3973]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 04 15:50:42 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 04 15:50:42 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 04 15:50:42 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 04 15:50:42 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 04 15:50:42 volumio sudo[3970]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:42 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 04 15:50:42 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Nov 04 15:50:42 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 04 15:50:42 volumio volumio[975]: info: Shairport-Sync Started Nov 04 15:50:42 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 04 15:50:42 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 04 15:50:42 volumio sudo[3973]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:42 volumio volumio[975]: info: Shairport-Sync Started Nov 04 15:50:43 volumio mpd[3974]: Nov 04 15:50 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 04 15:50:43 volumio systemd[1]: Started Music Player Daemon. Nov 04 15:50:43 volumio sudo[3954]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:43 volumio sudo[3945]: pam_unix(sudo:session): session closed for user root Nov 04 15:50:43 volumio volumio[975]: error: MPD error: The expression evaluated to a falsy value: Nov 04 15:50:43 volumio volumio[975]: assert.ok(self.idling) Nov 04 15:50:43 volumio volumio[975]: error: The expression evaluated to a falsy value: Nov 04 15:50:43 volumio volumio[975]: assert.ok(self.idling) Nov 04 15:50:43 volumio volumio[975]: error: updateQueue error: null Nov 04 15:50:43 volumio volumio[975]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Nov 04 15:50:43 volumio volumio[975]: info: Sending Spotify command with payload to local API: /player/volume Nov 04 15:50:43 volumio go-librespot[1267]: time="2025-11-04T15:50:43Z" level=debug msg="update volume requested to 56360/65535" Nov 04 15:50:43 volumio go-librespot[1267]: time="2025-11-04T15:50:43Z" level=debug msg="put connect state because VOLUME_CHANGED" Nov 04 15:50:43 volumio go-librespot[1267]: time="2025-11-04T15:50:43Z" level=trace msg="emitting websocket event: volume" Nov 04 15:50:43 volumio volumio[975]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Nov 04 15:50:43 volumio volumio[975]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Nov 04 15:50:45 volumio volumio[975]: info: CoreCommandRouter::volumioRetrieveVolumeLevels Nov 04 15:50:45 volumio volumio[975]: info: CoreStateMachine::getcurrentVolume Nov 04 15:50:45 volumio volumio[975]: info: CoreCommandRouter::volumioRetrievevolume Nov 04 15:50:45 volumio volumio[975]: info: VolumeController:: Volume=86 Mute =false Nov 04 15:50:45 volumio volumio[975]: info: CoreStateMachine::pushState Nov 04 15:50:45 volumio volumio[975]: info: CoreCommandRouter::volumioPushState Nov 04 15:50:45 volumio volumio[975]: info: CoreStateMachine::updateTrackBlock Nov 04 15:50:45 volumio volumio[975]: info: CorePlayQueue::getTrackBlock Nov 04 15:50:45 volumio volumio[975]: info: CoreCommandRouter::volumioRetrievevolume Nov 04 15:50:45 volumio volumio[975]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Nov 04 15:50:46 volumio volumio[975]: info: VolumeController:: Volume=86 Mute =false Nov 04 15:50:46 volumio volumio[975]: info: CoreStateMachine::pushState Nov 04 15:50:46 volumio volumio[975]: info: CoreCommandRouter::volumioPushState Nov 04 15:50:46 volumio volumio[975]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::volumioVolatilePlay Nov 04 15:50:51 volumio volumio[975]: info: CoreStateMachine::volatilePlay Nov 04 15:50:51 volumio volumio[975]: info: Spotify Play Nov 04 15:50:51 volumio volumio[975]: info: Sending Spotify command to local API: /player/resume Nov 04 15:50:51 volumio go-librespot[1267]: time="2025-11-04T15:50:51Z" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:73TxYZd0lBCVRrHawrAglA" Nov 04 15:50:51 volumio go-librespot[1267]: time="2025-11-04T15:50:51Z" level=trace msg="seek to 32257ms (diff: 168ms, samples: 1422533, bytes: 1438578)" uri="spotify:track:73TxYZd0lBCVRrHawrAglA" Nov 04 15:50:51 volumio go-librespot[1267]: time="2025-11-04T15:50:51Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Nov 04 15:50:51 volumio go-librespot[1267]: time="2025-11-04T15:50:51Z" level=debug msg="resume track at 32089ms" Nov 04 15:50:51 volumio go-librespot[1267]: time="2025-11-04T15:50:51Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 04 15:50:51 volumio go-librespot[1267]: time="2025-11-04T15:50:51Z" level=trace msg="scheduling prefetch in 212s" Nov 04 15:50:51 volumio go-librespot[1267]: time="2025-11-04T15:50:51Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 04 15:50:51 volumio go-librespot[1267]: time="2025-11-04T15:50:51Z" level=trace msg="emitting websocket event: playing" Nov 04 15:50:51 volumio volumio[975]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:73TxYZd0lBCVRrHawrAglA","resume":true,"play_origin":"playlist"}} Nov 04 15:50:51 volumio volumio[975]: SPOTIFY: PUSH STATE SPOTIFY Nov 04 15:50:51 volumio volumio[975]: SPOTIFY: {"status":"play","service":"spop","title":"Sweet Emotion","artist":"Aerosmith","album":"Toys In The Attic","albumart":"https://i.scdn.co/image/ab67616d00001e028cffbbb7fe8645a486a85ea9","uri":"spotify:track:73TxYZd0lBCVRrHawrAglA","trackType":"spotify","seek":32000,"duration":274,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::servicePushState Nov 04 15:50:51 volumio volumio[975]: info: CoreStateMachine::pushState Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::volumioPushState Nov 04 15:50:51 volumio volumio[975]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 04 15:50:51 volumio volumio[975]: info: Discovery: Getting this device information Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 04 15:50:51 volumio volumio[975]: SPOTIFY: PUSH STATE SPOTIFY Nov 04 15:50:51 volumio volumio[975]: SPOTIFY: {"status":"play","service":"spop","title":"Sweet Emotion","artist":"Aerosmith","album":"Toys In The Attic","albumart":"https://i.scdn.co/image/ab67616d00001e028cffbbb7fe8645a486a85ea9","uri":"spotify:track:73TxYZd0lBCVRrHawrAglA","trackType":"spotify","seek":32000,"duration":274,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::servicePushState Nov 04 15:50:51 volumio volumio[975]: info: CoreStateMachine::pushState Nov 04 15:50:51 volumio volumio[975]: info: CoreCommandRouter::volumioPushState Nov 04 15:50:51 volumio volumio[975]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Nov 04 15:50:52 volumio go-librespot[1267]: time="2025-11-04T15:50:52Z" level=trace msg="received accesspoint ping" Nov 04 15:50:52 volumio go-librespot[1267]: time="2025-11-04T15:50:52Z" level=trace msg="received accesspoint pong ack" Nov 04 15:50:53 volumio go-librespot[1267]: time="2025-11-04T15:50:53Z" level=trace msg="sent dealer ping" Nov 04 15:50:53 volumio go-librespot[1267]: time="2025-11-04T15:50:53Z" level=trace msg="received dealer pong" Nov 04 15:51:21 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 04 15:51:21 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 04 15:51:21 volumio volumio[975]: info: Discovery: Getting this device information Nov 04 15:51:21 volumio volumio[975]: info: CoreCommandRouter::volumioGetState Nov 04 15:51:21 volumio volumio[975]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 04 15:51:23 volumio go-librespot[1267]: time="2025-11-04T15:51:23Z" level=trace msg="sent dealer ping" Nov 04 15:51:23 volumio go-librespot[1267]: time="2025-11-04T15:51:23Z" level=trace msg="received dealer pong" Nov 04 15:51:38 volumio volumio[975]: info: ___________ PLUGINS: Run onVolumioReboot Tasks ___________ Nov 04 15:51:38 volumio volumio[975]: info: PLUGIN onReboot : networkfs Nov 04 15:51:38 volumio volumio[975]: info: PLUGIN onReboot : audiophonicsonoff Nov 04 15:51:38 volumio volumio[975]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 04 15:51:38 volumio volumio[975]: TypeError: Cannot read property 'writeSync' of undefined Nov 04 15:51:38 volumio volumio[975]: at ControllerAudiophonicsOnOff.onVolumioReboot (/data/plugins/system_controller/audiophonicsonoff/index.js:35:25) Nov 04 15:51:38 volumio volumio[975]: at PluginManager.onVolumioRebootPlugin (/volumio/app/pluginmanager.js:684:30) Nov 04 15:51:38 volumio volumio[975]: at HashMap. (/volumio/app/pluginmanager.js:668:31) Nov 04 15:51:38 volumio volumio[975]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Nov 04 15:51:38 volumio volumio[975]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Nov 04 15:51:38 volumio volumio[975]: at PluginManager.onVolumioReboot (/volumio/app/pluginmanager.js:666:20) Nov 04 15:51:38 volumio volumio[975]: at CoreCommandRouter.reboot (/volumio/app/index.js:1350:22) Nov 04 15:51:38 volumio volumio[975]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:870:33) Nov 04 15:51:38 volumio volumio[975]: at Socket.emit (events.js:315:20) Nov 04 15:51:38 volumio volumio[975]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Nov 04 15:51:38 volumio volumio[975]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Nov 04 15:51:38 volumio volumio[975]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 04 15:51:38 volumio sudo[4130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-11-04 15:50 Nov 04 15:51:38 volumio sudo[4130]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"