-- Logs begin at Thu 2025-10-23 21:21:44 BST, end at Thu 2025-10-23 21:32:16 BST. -- Oct 23 21:31:02 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 21:31:02 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 21:31:02 volumio volumio[977]: info: Discovery: Getting this device information Oct 23 21:31:02 volumio volumio[977]: info: CoreCommandRouter::volumioGetState Oct 23 21:31:02 volumio volumio[977]: info: CorePlayQueue::getTrack 0 Oct 23 21:31:02 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 21:31:03 volumio volumio[977]: info: Preload queue cleared Oct 23 21:31:06 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Oct 23 21:31:06 volumio volumio[977]: info: In handleBrowseUri, curUri=spotify:album:3DECdyclKlikXXh6jN4EnC Oct 23 21:31:07 volumio volumio[977]: info: Preload queue cleared Oct 23 21:31:07 volumio volumio[977]: info: Preloading song: spotify:track:3cyoi2F0g6dToeW5KmYFnp Oct 23 21:31:07 volumio volumio[977]: info: Exploding uri spotify:track:3cyoi2F0g6dToeW5KmYFnp in service spop Oct 23 21:31:07 volumio volumio[977]: SPOTIFY: EXPLODING URI:spotify:track:3cyoi2F0g6dToeW5KmYFnp Oct 23 21:31:07 volumio volumio[977]: info: No valid Plugin REST Endpoint Oct 23 21:31:07 volumio volumio[977]: info: No valid Plugin REST Endpoint Oct 23 21:31:07 volumio volumio[977]: info: No valid Plugin REST Endpoint Oct 23 21:31:07 volumio volumio[977]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:3cyoi2F0g6dToeW5KmYFnp","service":"spop","name":"Zaman Olur","artist":"Zeynep Özyılmazel","album":"Zaman Olur","type":"song","duration":245,"albumart":"https://i.scdn.co/image/ab67616d0000b27394db58579ee61ed578142aad","samplerate":"160 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Oct 23 21:31:08 volumio go-librespot[1245]: time="2025-10-23T21:31:08+01:00" level=trace msg="received accesspoint ping" Oct 23 21:31:08 volumio go-librespot[1245]: time="2025-10-23T21:31:08+01:00" level=trace msg="received accesspoint pong ack" Oct 23 21:31:08 volumio go-librespot[1245]: time="2025-10-23T21:31:08+01:00" level=trace msg="sent dealer ping" Oct 23 21:31:08 volumio go-librespot[1245]: time="2025-10-23T21:31:08+01:00" level=trace msg="received dealer pong" Oct 23 21:31:10 volumio volumio[977]: info: Preload queue cleared Oct 23 21:31:10 volumio volumio[977]: info: CoreCommandRouter::volumioReplaceandPlayItems Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::ClearQueue Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::stop Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 21:31:10 volumio volumio[977]: info: CorePlayQueue::clearPlayQueue Oct 23 21:31:10 volumio volumio[977]: info: CorePlayQueue::saveQueue Oct 23 21:31:10 volumio volumio[977]: info: CoreCommandRouter::volumioPushQueue Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::addQueueItems Oct 23 21:31:10 volumio volumio[977]: info: CorePlayQueue::addQueueItems Oct 23 21:31:10 volumio volumio[977]: info: Preload queue cleared Oct 23 21:31:10 volumio volumio[977]: info: Adding Item to queue: spotify:album:3DECdyclKlikXXh6jN4EnC Oct 23 21:31:10 volumio volumio[977]: info: Exploding uri spotify:album:3DECdyclKlikXXh6jN4EnC in service spop Oct 23 21:31:10 volumio volumio[977]: SPOTIFY: EXPLODING URI:spotify:album:3DECdyclKlikXXh6jN4EnC Oct 23 21:31:10 volumio volumio[977]: info: CoreCommandRouter::volumioPushQueue Oct 23 21:31:10 volumio volumio[977]: info: CorePlayQueue::saveQueue Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::updateTrackBlock Oct 23 21:31:10 volumio volumio[977]: info: CorePlayQueue::getTrackBlock Oct 23 21:31:10 volumio volumio[977]: info: CoreCommandRouter::volumioPlay Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::play index 0 Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::stop Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::play index undefined Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 23 21:31:10 volumio volumio[977]: info: CorePlayQueue::getTrack 0 Oct 23 21:31:10 volumio volumio[977]: info: CoreStateMachine::startPlaybackTimer Oct 23 21:31:10 volumio volumio[977]: info: CorePlayQueue::getTrack 0 Oct 23 21:31:10 volumio volumio[977]: info: [1761251470710] ControllerSpotify::clearAddPlayTrack Oct 23 21:31:10 volumio volumio[977]: info: Sending Spotify command with payload to local API: /player/play Oct 23 21:31:10 volumio go-librespot[1245]: time="2025-10-23T21:31:10+01:00" level=debug msg="resolved context of track" uri="spotify:track:3cyoi2F0g6dToeW5KmYFnp" Oct 23 21:31:10 volumio go-librespot[1245]: time="2025-10-23T21:31:10+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3cyoi2F0g6dToeW5KmYFnp" Oct 23 21:31:10 volumio go-librespot[1245]: time="2025-10-23T21:31:10+01:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:3cyoi2F0g6dToeW5KmYFnp" Oct 23 21:31:12 volumio go-librespot[1245]: time="2025-10-23T21:31:12+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 23 21:31:12 volumio go-librespot[1245]: time="2025-10-23T21:31:12+01:00" level=trace msg="emitting websocket event: will_play" Oct 23 21:31:12 volumio volumio[977]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3cyoi2F0g6dToeW5KmYFnp","uri":"spotify:track:3cyoi2F0g6dToeW5KmYFnp","play_origin":"go-librespot"}} Oct 23 21:31:12 volumio go-librespot[1245]: time="2025-10-23T21:31:12+01:00" level=debug msg="selected format OGG_VORBIS_160 (ada1cd4fecec2ae92cbaa74c702f2fe9738e4b85)" uri="spotify:track:3cyoi2F0g6dToeW5KmYFnp" Oct 23 21:31:12 volumio go-librespot[1245]: time="2025-10-23T21:31:12+01:00" level=debug msg="requested aes key for file ada1cd4fecec2ae92cbaa74c702f2fe9738e4b85, gid: 3cyoi2F0g6dToeW5KmYFnp" Oct 23 21:31:12 volumio go-librespot[1245]: time="2025-10-23T21:31:12+01:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3cyoi2F0g6dToeW5KmYFnp: failed retrieving audio key: failed retrieving aes key with code 1" Oct 23 21:31:12 volumio volumio[977]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Oct 23 21:31:29 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 23 21:31:29 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 23 21:31:29 volumio volumio[977]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 23 21:31:29 volumio volumio[977]: info: FusionDsp - Oct 23 21:31:30 volumio volumio[977]: info: FusionDsp - undefined Oct 23 21:31:32 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 21:31:32 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 21:31:32 volumio volumio[977]: info: Discovery: Getting this device information Oct 23 21:31:32 volumio volumio[977]: info: CoreCommandRouter::volumioGetState Oct 23 21:31:32 volumio volumio[977]: info: CorePlayQueue::getTrack 0 Oct 23 21:31:32 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 21:31:38 volumio go-librespot[1245]: time="2025-10-23T21:31:38+01:00" level=trace msg="sent dealer ping" Oct 23 21:31:38 volumio go-librespot[1245]: time="2025-10-23T21:31:38+01:00" level=trace msg="received dealer pong" Oct 23 21:31:55 volumio volumio[977]: info: Starting Uninstall of plugin system_controller - ampswitch Oct 23 21:31:55 volumio volumio[977]: info: Uninstalling plugin ampswitch Oct 23 21:31:55 volumio volumio[977]: info: [ASDebug] Port: 24 Oct 23 21:31:55 volumio volumio[977]: info: [ASDebug] Inverted: false Oct 23 21:31:55 volumio volumio[977]: info: [ASDebug] Delay: 720 Oct 23 21:31:59 volumio volumio[977]: info: Starting Uninstall of plugin audio_interface - mpdoutput Oct 23 21:31:59 volumio volumio[977]: info: Uninstalling plugin mpdoutput Oct 23 21:31:59 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: mpd , restartMpd Oct 23 21:31:59 volumio volumio[977]: info: Disabling plugin mpdoutput Oct 23 21:31:59 volumio sudo[2725]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 23 21:31:59 volumio sudo[2725]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 23 21:31:59 volumio volumio[977]: info: Checking if uninstall.sh is present Oct 23 21:31:59 volumio volumio[977]: info: Executing uninstall.sh Oct 23 21:31:59 volumio systemd[1]: Stopping Music Player Daemon... Oct 23 21:32:00 volumio systemd[1]: mpd.service: Succeeded. Oct 23 21:32:00 volumio systemd[1]: Stopped Music Player Daemon. Oct 23 21:32:00 volumio systemd[1]: Starting Music Player Daemon... Oct 23 21:32:00 volumio sudo[2729]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/audio_interface/mpdoutput/uninstall.sh Oct 23 21:32:00 volumio sudo[2729]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 23 21:32:00 volumio sudo[2729]: pam_unix(sudo:session): session closed for user root Oct 23 21:32:00 volumio volumio[977]: info: Uninstall script completed Oct 23 21:32:00 volumio volumio[977]: info: Removing plugin mpdoutput from configuration Oct 23 21:32:00 volumio sudo[2730]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 23 21:32:00 volumio sudo[2730]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 23 21:32:00 volumio sudo[2730]: pam_unix(sudo:session): session closed for user root Oct 23 21:32:00 volumio volumio[977]: info: Successfully removed mpdoutput configuration files Oct 23 21:32:00 volumio volumio[977]: info: Plugin folders cleanup Oct 23 21:32:00 volumio volumio[977]: info: Scanning into folder /volumio/app/plugins/ Oct 23 21:32:00 volumio volumio[977]: info: Scanning category audio_interface Oct 23 21:32:00 volumio volumio[977]: info: Scanning category miscellanea Oct 23 21:32:00 volumio volumio[977]: info: Scanning category music_service Oct 23 21:32:00 volumio volumio[977]: info: Scanning category plugins.json Oct 23 21:32:00 volumio volumio[977]: info: Scanning category system_controller Oct 23 21:32:00 volumio volumio[977]: info: Scanning category user_interface Oct 23 21:32:00 volumio volumio[977]: info: Scanning into folder /data/plugins/ Oct 23 21:32:00 volumio volumio[977]: info: Scanning category audio_interface Oct 23 21:32:00 volumio volumio[977]: info: Cleaning folder for mpdoutput Oct 23 21:32:00 volumio volumio[977]: info: Scanning category music_service Oct 23 21:32:00 volumio volumio[977]: info: Scanning category system_controller Oct 23 21:32:00 volumio volumio[977]: info: Plugin folders cleanup completed Oct 23 21:32:00 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 23 21:32:00 volumio volumio[977]: info: [{"prettyName":"FusionDsp","name":"fusiondsp","category":"audio_interface","version":"1.0.61","icon":"fa-sliders fa-rotate-90","isManuallyInstalled":true,"enabled":true,"active":true},{"prettyName":"Spotify","name":"spop","category":"music_service","version":"4.3.0","icon":"fa-spotify","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"YouTube Cast Receiver","name":"ytcr","category":"music_service","version":"1.2.0","icon":"fa-youtube","isManuallyInstalled":false,"enabled":false,"active":false},{"prettyName":"Amplifier Switch","name":"ampswitch","category":"system_controller","version":"0.2.1","icon":"fa-power-off","isManuallyInstalled":false,"enabled":true,"active":false},{"prettyName":"AutoStart","name":"autostart","category":"system_controller","version":"3.0.4","icon":"fa-lightbulb-o","isManuallyInstalled":false,"enabled":true,"active":true}] Oct 23 21:32:00 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Oct 23 21:32:00 volumio volumio[977]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 23 21:32:00 volumio volumio[977]: info: FusionDsp - Oct 23 21:32:01 volumio volumio[977]: info: FusionDsp - undefined Oct 23 21:32:02 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 23 21:32:02 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 23 21:32:02 volumio volumio[977]: info: Discovery: Getting this device information Oct 23 21:32:02 volumio volumio[977]: info: CoreCommandRouter::volumioGetState Oct 23 21:32:02 volumio volumio[977]: info: CorePlayQueue::getTrack 0 Oct 23 21:32:02 volumio volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 23 21:32:03 volumio mpd[2735]: Oct 23 21:32 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 23 21:32:03 volumio systemd[1]: Started Music Player Daemon. Oct 23 21:32:03 volumio sudo[2725]: pam_unix(sudo:session): session closed for user root Oct 23 21:32:03 volumio volumio[977]: error: updateQueue error: null Oct 23 21:32:08 volumio go-librespot[1245]: time="2025-10-23T21:32:08+01:00" level=trace msg="sent dealer ping" Oct 23 21:32:08 volumio go-librespot[1245]: time="2025-10-23T21:32:08+01:00" level=trace msg="received dealer pong" Oct 23 21:32:15 volumio volumio[977]: info: Starting Uninstall of plugin system_controller - ampswitch Oct 23 21:32:15 volumio volumio[977]: info: Uninstalling plugin ampswitch Oct 23 21:32:15 volumio volumio[977]: info: [ASDebug] Port: 24 Oct 23 21:32:15 volumio volumio[977]: info: [ASDebug] Inverted: false Oct 23 21:32:15 volumio volumio[977]: info: [ASDebug] Delay: 720 Oct 23 21:32:15 volumio volumio[977]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 21:32:15 volumio volumio[977]: Error: EBADF: bad file descriptor, close Oct 23 21:32:15 volumio volumio[977]: at Object.closeSync (fs.js:439:3) Oct 23 21:32:15 volumio volumio[977]: at Object.closeSync (/volumio/node_modules/graceful-fs/graceful-fs.js:74:20) Oct 23 21:32:15 volumio volumio[977]: at Object.closeSync (/data/plugins/system_controller/ampswitch/node_modules/graceful-fs/graceful-fs.js:51:27) Oct 23 21:32:15 volumio volumio[977]: at Gpio.unexport (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:307:8) Oct 23 21:32:15 volumio volumio[977]: at AmpSwitchController.freeGPIO (/data/plugins/system_controller/ampswitch/index.js:242:19) Oct 23 21:32:15 volumio volumio[977]: at AmpSwitchController.onStop (/data/plugins/system_controller/ampswitch/index.js:90:10) Oct 23 21:32:15 volumio volumio[977]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Oct 23 21:32:15 volumio volumio[977]: at PluginManager.unInstallPlugin (/volumio/app/pluginmanager.js:1449:10) Oct 23 21:32:15 volumio volumio[977]: at CoreCommandRouter.unInstallPlugin (/volumio/app/index.js:1484:22) Oct 23 21:32:15 volumio volumio[977]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1260:45) Oct 23 21:32:15 volumio volumio[977]: at Socket.emit (events.js:315:20) Oct 23 21:32:15 volumio volumio[977]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 23 21:32:15 volumio volumio[977]: at processTicksAndRejections (internal/process/task_queues.js:75:11) { Oct 23 21:32:15 volumio volumio[977]: errno: -9, Oct 23 21:32:15 volumio volumio[977]: syscall: 'close', Oct 23 21:32:15 volumio volumio[977]: code: 'EBADF' Oct 23 21:32:15 volumio volumio[977]: } Oct 23 21:32:15 volumio volumio[977]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 23 21:32:16 volumio sudo[2767]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-10-23 21:31 Oct 23 21:32:16 volumio sudo[2767]: 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"