-- Logs begin at Fri 2024-10-25 19:18:33 CEST, end at Sat 2024-10-26 12:13:48 CEST. -- Oct 26 12:12:08 volumio-pi go-librespot[1131]: time="2024-10-26T12:12:08+02:00" level=debug msg="fetched chunk 53/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:12:20 volumio-pi go-librespot[1131]: time="2024-10-26T12:12:20+02:00" level=debug msg="fetched chunk 54/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:12:21 volumio-pi volumio[955]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Oct 26 12:12:21 volumio-pi volumio[955]: verbose: ControllerMpd::sendMpdCommand update Oct 26 12:12:28 volumio-pi volumio[955]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Oct 26 12:12:28 volumio-pi volumio[955]: verbose: ControllerMpd::sendMpdCommand update Oct 26 12:12:32 volumio-pi go-librespot[1131]: time="2024-10-26T12:12:32+02:00" level=debug msg="fetched chunk 55/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:12:34 volumio-pi volumio[955]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 26 12:12:36 volumio-pi volumio[955]: info: Preload queue cleared Oct 26 12:12:39 volumio-pi volumio[955]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 26 12:12:39 volumio-pi volumio[955]: error: Error browsing13_c518959a:Error: Did not get expected response from server:{"Envelope":{"$":{"xmlns:SOAP-ENV":"http://schemas.xmlsoap.org/soap/envelope/","SOAP-ENV:encodingStyle":"http://schemas.xmlsoap.org/soap/encoding/"},"Body":[{"Fault":[{"faultcode":[{"_":"SOAP-ENV:Client"}],"faultstring":[{"_":"UPnPError"}],"detail":[{"UPnPError":[{"$":{"xmlns:u":"urn:schemas-upnp-org:control-1-0"},"errorCode":[{"_":"501"}],"errorDescription":[{"_":"Action Failed"}]}]}]}]}]}} Oct 26 12:12:39 volumio-pi volumio[955]: error: Failed to execute browseSource: Oct 26 12:12:41 volumio-pi volumiologrotate[614]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory Oct 26 12:12:41 volumio-pi volumiologrotate[614]: ls: cannot access 'PI': No such file or directory Oct 26 12:12:42 volumio-pi volumio[955]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 26 12:12:42 volumio-pi volumio[955]: info: Preload queue cleared Oct 26 12:12:43 volumio-pi volumio[955]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 26 12:12:43 volumio-pi volumio[955]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 12:12:43 volumio-pi volumio[955]: TypeError: Cannot read property 'length' of undefined Oct 26 12:12:43 volumio-pi volumio[955]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Oct 26 12:12:43 volumio-pi volumio[955]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Oct 26 12:12:43 volumio-pi volumio[955]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Oct 26 12:12:43 volumio-pi volumio[955]: at Parser.emit (events.js:315:20) Oct 26 12:12:43 volumio-pi volumio[955]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Oct 26 12:12:43 volumio-pi volumio[955]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Oct 26 12:12:43 volumio-pi volumio[955]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Oct 26 12:12:43 volumio-pi volumio[955]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Oct 26 12:12:43 volumio-pi volumio[955]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Oct 26 12:12:43 volumio-pi volumio[955]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Oct 26 12:12:43 volumio-pi volumio[955]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Oct 26 12:12:43 volumio-pi volumio[955]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Oct 26 12:12:43 volumio-pi volumio[955]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Oct 26 12:12:43 volumio-pi volumio[955]: at IncomingMessage.emit (events.js:327:22) Oct 26 12:12:43 volumio-pi volumio[955]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 26 12:12:43 volumio-pi volumio[955]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 26 12:12:43 volumio-pi volumio[955]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 12:12:43 volumio-pi sudo[8418]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-26 12:11 Oct 26 12:12:43 volumio-pi sudo[8418]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:43 volumio-pi sudo[8418]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:44 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:12:44] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 26 12:12:44 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:12:44] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 26 12:12:44 volumio-pi go-librespot[1131]: time="2024-10-26T12:12:44+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Oct 26 12:12:44 volumio-pi systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 26 12:12:44 volumio-pi systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 26 12:12:44 volumio-pi systemd[1]: Started dynamicswap service. Oct 26 12:12:44 volumio-pi systemd[1]: dynamicswap.service: Succeeded. Oct 26 12:12:44 volumio-pi systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 26 12:12:44 volumio-pi systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Oct 26 12:12:44 volumio-pi systemd[1]: Started dynamicswap service. Oct 26 12:12:44 volumio-pi systemd[1]: Stopped Volumio Backend Module. Oct 26 12:12:44 volumio-pi systemd[1]: Started Volumio Backend Module. Oct 26 12:12:44 volumio-pi systemd[1]: dynamicswap.service: Succeeded. Oct 26 12:12:44 volumio-pi go-librespot[1131]: time="2024-10-26T12:12:44+02:00" level=debug msg="fetched chunk 56/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:12:45 volumio-pi volumio[8433]: info: ------------------------------------------- Oct 26 12:12:45 volumio-pi volumio[8433]: info: ----- Volumio3 ---- Oct 26 12:12:45 volumio-pi volumio[8433]: info: ------------------------------------------- Oct 26 12:12:45 volumio-pi volumio[8433]: info: ----- System startup ---- Oct 26 12:12:45 volumio-pi volumio[8433]: info: ------------------------------------------- Oct 26 12:12:46 volumio-pi volumio[8433]: info: MYVOLUMIO Environment detected Oct 26 12:12:46 volumio-pi volumio[8433]: info: Plugin folders cleanup Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning into folder /volumio/app/plugins/ Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning category audio_interface Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning category miscellanea Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning category music_service Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning category plugins.json Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning category system_controller Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning category user_interface Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning into folder /data/plugins/ Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning category music_service Oct 26 12:12:46 volumio-pi volumio[8433]: info: Scanning category system_controller Oct 26 12:12:46 volumio-pi volumio[8433]: info: Plugin folders cleanup completed Oct 26 12:12:46 volumio-pi volumio[8433]: info: ------------------------------------------- Oct 26 12:12:46 volumio-pi volumio[8433]: info: ----- Core plugins startup ---- Oct 26 12:12:46 volumio-pi volumio[8433]: info: ------------------------------------------- Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugins from folder /volumio/app/plugins/ Oct 26 12:12:46 volumio-pi volumio[8433]: info: Adding plugin upnp to MyMusic Plugins Oct 26 12:12:46 volumio-pi volumio[8433]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 26 12:12:46 volumio-pi volumio[8433]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugins from folder /data/plugins/ Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "system"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "appearance"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "network"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: Refreshing Cached IP Addresses Oct 26 12:12:46 volumio-pi sudo[8459]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 12:12:46 volumio-pi sudo[8459]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:46 volumio-pi sudo[8459]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:46 volumio-pi sudo[8461]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 12:12:46 volumio-pi sudo[8461]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "services"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "alsa_controller"... Oct 26 12:12:46 volumio-pi sudo[8461]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:46 volumio-pi sudo[8464]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 26 12:12:46 volumio-pi sudo[8464]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:46 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "wizard"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "networkfs"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: Starting Udev Watcher for removable devices Oct 26 12:12:46 volumio-pi volumio[8433]: info: Ignoring mount for partition: boot Oct 26 12:12:46 volumio-pi volumio[8433]: info: Ignoring mount for partition: volumio Oct 26 12:12:46 volumio-pi volumio[8433]: info: Ignoring mount for partition: volumio_data Oct 26 12:12:46 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "volumio_command_line_client"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "upnp"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: [1729937566925] Starting Upmpd Daemon Oct 26 12:12:46 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "my_music"... Oct 26 12:12:46 volumio-pi volumio[8433]: info: Loading plugin "mpd"... Oct 26 12:12:47 volumio-pi volumio[8433]: info: Loading plugin "upnp_browser"... Oct 26 12:12:47 volumio-pi volumio[8433]: info: Loading plugin "alarm-clock"... Oct 26 12:12:47 volumio-pi volumio[8433]: info: Loading plugin "airplay_emulation"... Oct 26 12:12:47 volumio-pi volumio[8433]: info: Starting Shairport Sync Oct 26 12:12:47 volumio-pi volumio[8433]: info: Loading plugin "last_100"... Oct 26 12:12:47 volumio-pi volumio[8433]: info: Loading plugin "webradio"... Oct 26 12:12:47 volumio-pi volumio[8433]: info: Loading plugin "i2s_dacs"... Oct 26 12:12:47 volumio-pi volumio[8433]: info: Loading plugin "volumiodiscovery"... Oct 26 12:12:47 volumio-pi volumio[8433]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 12:12:47 volumio-pi node[8433]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 12:12:47 volumio-pi volumio[8433]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:12:47 volumio-pi node[8433]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:12:47 volumio-pi volumio[8433]: *** WARNING *** For more information see Oct 26 12:12:47 volumio-pi node[8433]: *** WARNING *** For more information see Oct 26 12:12:47 volumio-pi volumio[8433]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 12:12:47 volumio-pi node[8433]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 12:12:47 volumio-pi volumio[8433]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:12:47 volumio-pi node[8433]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:12:47 volumio-pi volumio[8433]: *** WARNING *** For more information see Oct 26 12:12:47 volumio-pi node[8433]: *** WARNING *** For more information see Oct 26 12:12:47 volumio-pi volumio[8433]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 26 12:12:47 volumio-pi volumio[8433]: info: Discovery: Started advertising with name: Volumio PI Oct 26 12:12:47 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:12:47 volumio-pi volumio[8433]: info: Loading plugin "spop"... Oct 26 12:12:48 volumio-pi volumio[8433]: info: Loading plugin "autostart"... Oct 26 12:12:48 volumio-pi volumio[8433]: info: Applying required configuration parameters for plugin autostart Oct 26 12:12:48 volumio-pi volumio[8433]: info: AutoStart - onVolumioStart - read config.json Oct 26 12:12:48 volumio-pi volumio[8433]: info: Loading plugin "outputs"... Oct 26 12:12:48 volumio-pi volumio[8433]: info: Loading plugin "albumart"... Oct 26 12:12:48 volumio-pi volumio[8433]: info: Plugin example_plugin is not enabled Oct 26 12:12:48 volumio-pi volumio[8433]: info: Loading plugin "inputs"... Oct 26 12:12:48 volumio-pi volumio[8433]: info: Loading plugin "updater_comm"... Oct 26 12:12:48 volumio-pi volumio[8433]: info: Plugin mpdemulation is not enabled Oct 26 12:12:48 volumio-pi volumio[8433]: info: Loading plugin "rest_api"... Oct 26 12:12:48 volumio-pi volumio[8433]: info: Loading plugin "websocket"... Oct 26 12:12:48 volumio-pi volumio[8433]: info: Starting Socket.io Server version 2.3.0 Oct 26 12:12:48 volumio-pi volumio[8433]: info: Loading i18n strings for locale da Oct 26 12:12:48 volumio-pi volumio[8433]: Updating browse sources language Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:12:48 volumio-pi volumio[8433]: Forking 3 albumart workers Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::initPlayerControls Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: Express server listening on port 3000 Oct 26 12:12:48 volumio-pi volumio[8433]: [Metrics] WebUI: 3s 287.77ms Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreStateMachine::resetVolumioState Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreStateMachine::getcurrentVolume Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 12:12:48 volumio-pi volumio[8433]: verbose: New Socket.io Connection to 192.168.50.211 from 192.168.50.139 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Edg/130.0.0.0 Engine version: 3 Transport: polling Total Clients: 1 Oct 26 12:12:48 volumio-pi volumio[8433]: verbose: New Socket.io Connection to 192.168.50.211 from 192.168.50.139 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Edg/130.0.0.0 Engine version: 3 Transport: polling Total Clients: 2 Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:48 volumio-pi volumio[8433]: info: Executing start script for DAC IQaudIO DAC Plus Oct 26 12:12:48 volumio-pi volumio[8433]: info: Reloading queue from file Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreStateMachine::setRepeat null single undefined Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:12:48 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreStateMachine::setRandom null Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:12:48 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:12:48 volumio-pi volumio[8433]: info: Setting Device type: Raspberry PI Oct 26 12:12:48 volumio-pi volumio[8433]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 26 12:12:48 volumio-pi volumio[8433]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03111 Oct 26 12:12:48 volumio-pi volumio[8433]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 26 12:12:48 volumio-pi volumio[8433]: info: VolumeController:: Volume=100 Mute =false Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:12:48 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreStateMachine::updateTrackBlock Oct 26 12:12:48 volumio-pi volumio[8433]: info: CorePlayQueue::getTrackBlock Oct 26 12:12:48 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 12:12:49 volumio-pi volumio[8433]: info: DAC script executed Oct 26 12:12:49 volumio-pi volumio[8433]: info: Completed loading Core Plugins Oct 26 12:12:49 volumio-pi volumio[8433]: info: Preparing to generate the ALSA configuration file Oct 26 12:12:49 volumio-pi volumio[8433]: info: Asound.conf file unchanged, so no further update is needed Oct 26 12:12:49 volumio-pi volumio[8433]: info: Output device has changed, restarting MPD Oct 26 12:12:49 volumio-pi volumio[8433]: Starting albumart workers Oct 26 12:12:49 volumio-pi volumio[8433]: info: Output device has changed, restarting Shairport Sync Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:49 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:12:49] [connect] Successful connection Oct 26 12:12:49 volumio-pi sudo[8519]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 12:12:49 volumio-pi sudo[8519]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:49 volumio-pi sudo[8520]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 12:12:49 volumio-pi sudo[8520]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:49 volumio-pi volumio[8433]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:12:49 volumio-pi volumio[8433]: info: ___________ START PLUGINS ___________ Oct 26 12:12:49 volumio-pi sudo[8519]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:49 volumio-pi volumio[8433]: info: ControllerMpd::onStart: Initializing MPD Oct 26 12:12:49 volumio-pi volumio[8433]: info: Creating MPD Configuration file Oct 26 12:12:49 volumio-pi systemd[1]: Stopping Music Player Daemon... Oct 26 12:12:49 volumio-pi sudo[8528]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:12:49 volumio-pi volumio[8433]: Starting albumart workers Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:12:49 volumio-pi volumio[8433]: info: [1729937569299] CoreMusicLibrary::Adding element Medieservere Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:12:49 volumio-pi sudo[8528]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:49 volumio-pi sudo[8528]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:49 volumio-pi sudo[8529]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 12:12:49 volumio-pi sudo[8529]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:49 volumio-pi volumio[8433]: Starting albumart workers Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:49 volumio-pi systemd[1]: mpd.service: Succeeded. Oct 26 12:12:49 volumio-pi systemd[1]: Stopped Music Player Daemon. Oct 26 12:12:49 volumio-pi volumio[8433]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:49 volumio-pi systemd[1]: Starting Music Player Daemon... Oct 26 12:12:49 volumio-pi volumio[8433]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:12:49 volumio-pi volumio[8433]: info: [1729937569457] CoreMusicLibrary::Adding element Last_100 Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:12:49 volumio-pi volumio[8433]: info: [1729937569459] CoreMusicLibrary::Adding element Webradio Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:12:49 volumio-pi volumio[8433]: info: Initializing BBC Radios Oct 26 12:12:49 volumio-pi sudo[8535]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 12:12:49 volumio-pi sudo[8535]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:49 volumio-pi sudo[8535]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:49 volumio-pi volumio[8433]: info: Creating Spotify config file Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:49 volumio-pi sudo[8464]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:49 volumio-pi volumio[8433]: info: AutoStart - onStart Oct 26 12:12:49 volumio-pi volumio[8433]: info: Volumio Calling Home Oct 26 12:12:49 volumio-pi volumio[8433]: info: Discovery: adding b37ff9d2-5853-457e-9dc0-bdd64172c9b7 Oct 26 12:12:49 volumio-pi volumio[8433]: info: Discovery: Found device Volumio PI Oct 26 12:12:49 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:12:49 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:50 volumio-pi volumio[8433]: info: MPD Permissions set Oct 26 12:12:50 volumio-pi volumio[8433]: info: MPD Permissions set Oct 26 12:12:50 volumio-pi volumio[8433]: info: VolumeController:: Volume=100 Mute =false Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:12:50 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:12:50 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:12:50] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1729937569 101 Oct 26 12:12:50 volumio-pi volumio[8433]: 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: 3 Oct 26 12:12:50 volumio-pi volumio[8433]: info: Volumio called home Oct 26 12:12:50 volumio-pi volumio[8433]: info: Spotify config file written Oct 26 12:12:50 volumio-pi volumio[8433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi sudo[8582]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 26 12:12:50 volumio-pi sudo[8582]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:50 volumio-pi systemd[1]: Stopping go-librespot Daemon... Oct 26 12:12:50 volumio-pi systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi systemd[1]: go-librespot-daemon.service: Succeeded. Oct 26 12:12:50 volumio-pi systemd[1]: Stopped go-librespot Daemon. Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:12:50 volumio-pi volumio[8433]: info: No need to fix Spotify hosts Oct 26 12:12:50 volumio-pi systemd[1]: Started go-librespot Daemon. Oct 26 12:12:50 volumio-pi go-librespot[8590]: Librespot-go daemon starting... Oct 26 12:12:50 volumio-pi sudo[8582]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=info msg="generated new device id: 84e9700f8dc66c01661ebaaccda4ae390652e75e" Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=debug msg="stored credentials found for 313le7g4thoej6cykmoa3argwfme" Oct 26 12:12:50 volumio-pi volumio[8433]: info: Starting Shairport Sync Oct 26 12:12:50 volumio-pi volumio[8433]: info: Starting Shairport Sync Oct 26 12:12:50 volumio-pi sudo[8602]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:12:50 volumio-pi sudo[8602]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:50 volumio-pi volumio[8433]: info: Starting Shairport Sync Oct 26 12:12:50 volumio-pi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 12:12:50 volumio-pi systemd[1]: shairport-sync.service: Succeeded. Oct 26 12:12:50 volumio-pi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 12:12:50 volumio-pi sudo[8606]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:12:50 volumio-pi sudo[8606]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:50 volumio-pi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:12:50 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:50 volumio-pi sudo[8608]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:12:50 volumio-pi sudo[8608]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:50 volumio-pi sudo[8602]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=debug msg="zeroconf server listening on port 35087" Oct 26 12:12:50 volumio-pi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 12:12:50 volumio-pi systemd[1]: shairport-sync.service: Succeeded. Oct 26 12:12:50 volumio-pi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 12:12:50 volumio-pi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 12:12:50 volumio-pi sudo[8608]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:50 volumio-pi sudo[8606]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=debug msg="obtained new client token: AAAu1ryVNegUcc0DRjwDndpjyfmBfFCJZavEmYk5uE6pix1+CS9um1p2fYLyqgrzVs+qLaa9AbMKcu+5M928UmXZc5RNHU7TqVSQtUsBSkiO489YsbBpnQG7eX83krFzy4esX0yMb3kPtEU1gKhGdcnTJJcYG3e8zxEmndyX7FU77OOVKS8ryNNtNBjPJM0Om0DBOZdMIve8vN5qJi7LgmAWoQi/VrqqFnECzbZ9a+w6cdls1xFj4t+SrGpqqQ==" Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Oct 26 12:12:50 volumio-pi volumio[8433]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 12:12:50 volumio-pi volumio[8433]: SPOTIFY: BQDCmssDoF12GzuNOEYIpfM-siNi3YWyRf6SrJdV-s1XGBS3YFC0MTebjKzsCuqvyYuhURm0roeD9_wDEydhiO1mjE0xvFhC-NC35bCRn4qLbSTZOHh7HWrGMIR4aSkkFfmf-r_LtLZ9c3rVPmwEg3mp2y2xrSWhzmQ6QDJ-DHl_zRBkxi_BxAyK5G7vkVNg061E2CuySZCC8h599NzWf_2bntYv625tuMxstyPZrDmlD0kJKVFPJNnjEPtNlyh2KQtF7E3ljwxO4TuH08s Oct 26 12:12:50 volumio-pi volumio[8433]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 12:12:50 volumio-pi volumio[8433]: info: New Spotify access token = BQDCmssDoF12GzuNOEYIpfM-siNi3YWyRf6SrJdV-s1XGBS3YFC0MTebjKzsCuqvyYuhURm0roeD9_wDEydhiO1mjE0xvFhC-NC35bCRn4qLbSTZOHh7HWrGMIR4aSkkFfmf-r_LtLZ9c3rVPmwEg3mp2y2xrSWhzmQ6QDJ-DHl_zRBkxi_BxAyK5G7vkVNg061E2CuySZCC8h599NzWf_2bntYv625tuMxstyPZrDmlD0kJKVFPJNnjEPtNlyh2KQtF7E3ljwxO4TuH08s Oct 26 12:12:50 volumio-pi volumio[8433]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 26 12:12:50 volumio-pi volumio[8433]: info: Shairport-Sync Started Oct 26 12:12:50 volumio-pi volumio[8433]: Error adding Membership: Error: addMembership EINVAL Oct 26 12:12:50 volumio-pi volumio[8433]: info: Shairport-Sync Started Oct 26 12:12:50 volumio-pi volumio[8433]: info: Shairport-Sync Started Oct 26 12:12:50 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:50+02:00" level=debug msg="completed keyexchange" Oct 26 12:12:50 volumio-pi mpd[8549]: Oct 26 12:12 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 26 12:12:50 volumio-pi systemd[1]: Started Music Player Daemon. Oct 26 12:12:50 volumio-pi sudo[8520]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:50 volumio-pi sudo[8529]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:50 volumio-pi volumio[8433]: info: Completed starting Core Plugins Oct 26 12:12:50 volumio-pi volumio[8433]: info: ------------------------------------------- Oct 26 12:12:50 volumio-pi volumio[8433]: info: ----- MyVolumio plugins startup ---- Oct 26 12:12:50 volumio-pi volumio[8433]: info: ------------------------------------------- Oct 26 12:12:50 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 26 12:12:50 volumio-pi volumio[8433]: error: MPD error: The expression evaluated to a falsy value: Oct 26 12:12:50 volumio-pi volumio[8433]: assert.ok(self.idling) Oct 26 12:12:50 volumio-pi volumio[8433]: error: The expression evaluated to a falsy value: Oct 26 12:12:50 volumio-pi volumio[8433]: assert.ok(self.idling) Oct 26 12:12:50 volumio-pi volumio[8433]: info: MPD running with PID8549 Oct 26 12:12:50 volumio-pi volumio[8433]: ,establishing connection Oct 26 12:12:50 volumio-pi volumio[8433]: error: updateQueue error: null Oct 26 12:12:50 volumio-pi volumio[8433]: error: updateQueue error: null Oct 26 12:12:50 volumio-pi volumio[8433]: SPOTIFY: User informations: {"country":"DK","display_name":"Carsten","email":"carstenbfrederiksen@outlook.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/313le7g4thoej6cykmoa3argwfme"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/313le7g4thoej6cykmoa3argwfme","id":"313le7g4thoej6cykmoa3argwfme","images":[],"product":"premium","type":"user","uri":"spotify:user:313le7g4thoej6cykmoa3argwfme"} Oct 26 12:12:50 volumio-pi volumio[8433]: info: Spotify Successfully logged in Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:12:50 volumio-pi volumio[8433]: info: [1729937570734] CoreMusicLibrary::Adding element Spotify Oct 26 12:12:50 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:12:50 volumio-pi volumio[8433]: Cannot find translation for source Spotify Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="completed challenge" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="authenticated as 313le7g4thoej6cykmoa3argwfme" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="authenticated as 313le7g4thoej6cykmoa3argwfme" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="dealer connection opened" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="initializing zeroconf session, username: 313le7g4thoej6cykmoa3argwfme" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="autoplay enabled: false" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="received connection id: YmEyZDNlMGQtODY5MS00NmM4LWE5ZTItMjgwZDU4ODBlYzU4K2RlYWxlcit0Y3A6Ly8wYWNhNThiMi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArN0NGNjY0MkMyMkY3RjFGMjVBMkFCRTlFM0FFRDIyRUE5OTNCMUQxMDYwMjU3MDdCRjE2RDI5OTQxNzRCQ0MzRQ==" Oct 26 12:12:51 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:51+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 26 12:12:52 volumio-pi volumio[8433]: verbose: New Socket.io Connection to 192.168.50.211 from 192.168.50.139 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Edg/130.0.0.0 Engine version: 3 Transport: polling Total Clients: 5 Oct 26 12:12:52 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetVisibleSources Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:12:53 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:12:53 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 26 12:12:53 volumio-pi volumio[8433]: info: Received Get System Info Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 12:12:53 volumio-pi volumio[8433]: info: Discovery: Getting this device information Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:12:53 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:12:53 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:12:53 volumio-pi volumio[8433]: info: Listing playlists Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetQueue Oct 26 12:12:53 volumio-pi volumio[8433]: info: CoreStateMachine::getQueue Oct 26 12:12:53 volumio-pi volumio[8433]: info: CorePlayQueue::getQueue Oct 26 12:12:53 volumio-pi volumio[8433]: info: go-librespot daemon successfully initialized Oct 26 12:12:55 volumio-pi volumio[8433]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 26 12:12:56 volumio-pi volumio[8433]: info: Initializing connection to go-librespot Websocket Oct 26 12:12:56 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:56+02:00" level=debug msg="new websocket client" Oct 26 12:12:56 volumio-pi volumio[8433]: info: Connection to go-librespot Websocket established Oct 26 12:12:56 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 26 12:12:56 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 26 12:12:56 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Oct 26 12:12:56 volumio-pi go-librespot[8590]: time="2024-10-26T12:12:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1457" Oct 26 12:12:56 volumio-pi sudo[8625]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 12:12:56 volumio-pi sudo[8625]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:56 volumio-pi sudo[8625]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:56 volumio-pi sudo[8628]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 12:12:56 volumio-pi sudo[8628]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:56 volumio-pi sudo[8628]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:56 volumio-pi sudo[8631]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 26 12:12:56 volumio-pi sudo[8631]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:12:57 volumio-pi sudo[8631]: pam_unix(sudo:session): session closed for user root Oct 26 12:12:57 volumio-pi volumio[8433]: info: Upmpdcli Daemon Started Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 26 12:12:59 volumio-pi volumio[8433]: info: Adding plugin bluetooth to MyMusic Plugins Oct 26 12:12:59 volumio-pi volumio[8433]: info: Adding plugin multiroom to MyMusic Plugins Oct 26 12:12:59 volumio-pi volumio[8433]: info: Adding plugin metavolumio to MyMusic Plugins Oct 26 12:12:59 volumio-pi volumio[8433]: info: Adding plugin cd_controller to MyMusic Plugins Oct 26 12:12:59 volumio-pi volumio[8433]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 26 12:12:59 volumio-pi volumio[8433]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 26 12:12:59 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:59 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:12:59 volumio-pi volumio[8433]: info: Starting MyVolumio Remote Streaming Endpoints Oct 26 12:12:59 volumio-pi volumio[8433]: info: MyVolumio login type: Token Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 26 12:12:59 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 26 12:13:00 volumio-pi volumio[8433]: info: Starting Streaming Service Transparent Proxy Oct 26 12:13:00 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 26 12:13:00 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 26 12:13:00 volumio-pi volumio[8433]: info: Streaming services startup Oct 26 12:13:00 volumio-pi volumio[8433]: info: Starting Streaming Daemon Oct 26 12:13:00 volumio-pi sudo[8640]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 12:13:00 volumio-pi sudo[8640]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:00 volumio-pi sudo[8640]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:00 volumio-pi volumio[8433]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 26 12:13:00 volumio-pi volumio[8433]: info: Getting Spotify volume Oct 26 12:13:00 volumio-pi volumio[8433]: error: Cannot start Volumio Streaming Daemon Oct 26 12:13:00 volumio-pi volumio[8433]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 12:13:00 volumio-pi volumio[8433]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 12:13:00 volumio-pi volumio[8433]: info: Spotify volume: 100 Oct 26 12:13:00 volumio-pi volumio[8433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Oct 26 12:13:00 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:00 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:00 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:00 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 26 12:13:00 volumio-pi volumio[8433]: error: MyVolumio Custom Token format not valid, refreshing it Oct 26 12:13:00 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Oct 26 12:13:01 volumio-pi volumio[8433]: STREAMING PROXY: Starting server on port 3245 Oct 26 12:13:01 volumio-pi volumio[8433]: Node JS runtime: 14 Oct 26 12:13:01 volumio-pi volumio[8433]: info: MyVolumio login type: Token Oct 26 12:13:01 volumio-pi volumio[8433]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 26 12:13:02 volumio-pi volumio[8433]: info: MyVolumio token set successfully Oct 26 12:13:02 volumio-pi volumio[8433]: info: MYVOLUMIO: Adding device Oct 26 12:13:02 volumio-pi volumio[8433]: info: MYVOLUMIO: Evaluating Server Oct 26 12:13:03 volumio-pi volumio[8433]: info: MyVolumio status changed Oct 26 12:13:03 volumio-pi volumio[8433]: info: Streaming services startup Oct 26 12:13:03 volumio-pi volumio[8433]: info: Starting Streaming Daemon Oct 26 12:13:03 volumio-pi volumio[8433]: info: Removing browser output: myVolumio user plan is not superstar Oct 26 12:13:03 volumio-pi volumio[8433]: info: Removing audio output: Oct 26 12:13:03 volumio-pi volumio[8433]: info: Stoppping Tunnel 1 Oct 26 12:13:03 volumio-pi sudo[8666]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 26 12:13:03 volumio-pi sudo[8666]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:03 volumio-pi sudo[8666]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:03 volumio-pi sudo[8669]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Oct 26 12:13:03 volumio-pi sudo[8669]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:03 volumio-pi volumio[8433]: error: Cannot start Volumio Streaming Daemon Oct 26 12:13:03 volumio-pi volumio[8433]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 26 12:13:03 volumio-pi volumio[8433]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 26 12:13:03 volumio-pi sudo[8669]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:03 volumio-pi volumio[8433]: info: Remote SSH Stopped Oct 26 12:13:03 volumio-pi volumio[8433]: info: Setting Geolocation for MyVolumio to eu4 Oct 26 12:13:03 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:03 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:03 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:03 volumio-pi volumio[8433]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 26 12:13:04 volumio-pi volumio[8433]: info: Updating MyVolumio device info Oct 26 12:13:04 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:04 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:04 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:04 volumio-pi volumio[8433]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="handling transfer player command from d4ddc4a8c15b2baedda9b3788de565d7515d63ed" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="resolved context of track" uri="spotify:album:14EWYgtvXZSz0pzvpUCsbL" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=trace msg="fetched new page 0 with 64 items (list: 64)" uri="spotify:album:14EWYgtvXZSz0pzvpUCsbL" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="loading track (paused: false, position: 645644ms)" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=trace msg="emitting websocket event: will_play" Oct 26 12:13:05 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","play_origin":"album"}} Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="selected format OGG_VORBIS_320 (f3f11e302ac1357c354ad972e5b271a51baa5687)" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="requested aes key for file f3f11e302ac1357c354ad972e5b271a51baa5687, gid: 1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1393" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="fetched first chunk of 66, total size is 34396776 bytes" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:05 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:05+02:00" level=debug msg="fetched chunk 1/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="fetched chunk 2/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="fetched chunk 3/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1152" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="fetched chunk 57/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="fetched chunk 56/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="fetched chunk 55/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="fetched chunk 54/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=trace msg="seek to 645644ms (diff: 226ms, samples: 28472900, bytes: 28404824)" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="created new output device" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=info msg="loaded track \"Telegraph Road - Live At Hammersmith Odeon, London / 1983 / Remastered 2023\" (paused: false, position: 645644ms, duration: 776106ms, prefetched: false)" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=trace msg="scheduling prefetch in 101s" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=trace msg="emitting websocket event: metadata" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=trace msg="emitting websocket event: active" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="sending successful reply for dealer request" Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","name":"Telegraph Road - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist_names":["Dire Straits"],"album_name":"Live 1978 - 1992","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","position":645644,"duration":776106,"release_date":"year:2023 month:11 day:3","track_number":13,"disc_number":1}} Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"active","data":null} Oct 26 12:13:06 volumio-pi volumio[8433]: info: Aligning Spotify Volume to Volumio Volume Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:06 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:06 volumio-pi volumio[8433]: info: Setting Spotify Volume from Volumio: 100 Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:06 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:06+02:00" level=trace msg="emitting websocket event: playing" Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","play_origin":"album"}} Oct 26 12:13:06 volumio-pi volumio[8433]: info: Spotify is playing in volatile mode Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: UNSET VOLATILE Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: {"status":"stop","position":0,"title":"Sortedam","artist":"Thomas Helmig","album":"Sortedam","albumart":"https://i.scdn.co/image/ab67616d0000b2732be877f4dc9c12e6dacd72ad","uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","trackType":"spotify","codec":"ogg","seek":0,"duration":242,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","updatedb":false,"volatile":false,"service":"spop"} Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","service":"spop","title":"Telegraph Road - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist":"Dire Straits","album":"Live 1978 - 1992","albumart":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","trackType":"spotify","seek":645644,"duration":776,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreCommandRouter::servicePushState Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","service":"spop","title":"Telegraph Road - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist":"Dire Straits","album":"Live 1978 - 1992","albumart":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","trackType":"spotify","seek":645644,"duration":776,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreCommandRouter::servicePushState Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:13:06 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:06 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:07 volumio-pi volumio[8433]: info: MYVOLUMIO: Adding device Oct 26 12:13:07 volumio-pi volumio[8433]: info: MYVOLUMIO: Evaluating Server Oct 26 12:13:07 volumio-pi volumio[8433]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Oct 26 12:13:07 volumio-pi volumio[8433]: info: Sending Spotify command with payload to local API: /player/volume Oct 26 12:13:08 volumio-pi volumio[8433]: info: Setting Geolocation for MyVolumio to eu10 Oct 26 12:13:08 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:08 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:08 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:08 volumio-pi volumio[8433]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Oct 26 12:13:09 volumio-pi volumio[8433]: info: Updating MyVolumio device info Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:09 volumio-pi volumio[8433]: info: AutoStart - Plugin is starting Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetQueue Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::getQueue Oct 26 12:13:09 volumio-pi volumio[8433]: info: CorePlayQueue::getQueue Oct 26 12:13:09 volumio-pi volumio[8433]: info: AutoStart - start playing Oct 26 12:13:09 volumio-pi volumio[8433]: info: AutoStart - start playing with no specific position Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPlay Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::play index 0 Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::stop Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::stPlaybackTimer Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::updateTrackBlock Oct 26 12:13:09 volumio-pi volumio[8433]: info: CorePlayQueue::getTrackBlock Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:13:09 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::serviceStop Oct 26 12:13:09 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreCommandRouter::serviceStop Oct 26 12:13:09 volumio-pi volumio[8433]: info: Spotify Stop Oct 26 12:13:09 volumio-pi volumio[8433]: SPOTIFY: SPOTIFY STOP Oct 26 12:13:09 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","title":"Telegraph Road - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist":"Dire Straits","album":"Live 1978 - 1992","albumart":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","trackType":"spotify","codec":"ogg","seek":645644,"duration":776,"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"} Oct 26 12:13:09 volumio-pi volumio[8433]: info: Sending Spotify command to local API: /player/pause Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::play index undefined Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 26 12:13:09 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:09 volumio-pi volumio[8433]: info: CoreStateMachine::startPlaybackTimer Oct 26 12:13:09 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:09 volumio-pi volumio[8433]: info: [1729937589807] ControllerSpotify::clearAddPlayTrack Oct 26 12:13:09 volumio-pi volumio[8433]: info: Sending Spotify command with payload to local API: /player/play Oct 26 12:13:09 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:09 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:09+02:00" level=debug msg="pause track at 648955ms" Oct 26 12:13:09 volumio-pi volumio[8433]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Oct 26 12:13:09 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:09 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:09+02:00" level=debug msg="resolved context of track" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:09 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:09+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:09 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:09+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:09 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:09+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:09 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:09+02:00" level=trace msg="emitting websocket event: will_play" Oct 26 12:13:09 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","play_origin":"go-librespot"}} Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="selected format OGG_VORBIS_320 (cc2a59a2cd79f646093121a1335f1a19b821d840)" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="requested aes key for file cc2a59a2cd79f646093121a1335f1a19b821d840, gid: 3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="fetched first chunk of 19, total size is 9493027 bytes" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:10 volumio-pi kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=info msg="loaded track \"Sortedam\" (paused: false, position: 1ms, duration: 242926ms, prefetched: false)" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=trace msg="scheduling prefetch in 213s" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=trace msg="emitting websocket event: metadata" Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","name":"Sortedam","artist_names":["Thomas Helmig"],"album_name":"Sortedam","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022be877f4dc9c12e6dacd72ad","position":1,"duration":242926,"release_date":"year:2024 month:10 day:25","track_number":1,"disc_number":1}} Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:3KKfy9c7s81AOoXbqd1obP" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=trace msg="emitting websocket event: paused" Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","play_origin":"go-librespot"}} Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: {"status":"pause","service":"spop","title":"Sortedam","artist":"Thomas Helmig","album":"Sortedam","albumart":"https://i.scdn.co/image/ab67616d00001e022be877f4dc9c12e6dacd72ad","uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","trackType":"spotify","seek":1,"duration":242,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreCommandRouter::servicePushState Oct 26 12:13:10 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:10 volumio-pi volumio[8433]: verbose: STATE SERVICE {"status":"pause","service":"spop","title":"Sortedam","artist":"Thomas Helmig","album":"Sortedam","albumart":"https://i.scdn.co/image/ab67616d00001e022be877f4dc9c12e6dacd72ad","uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","trackType":"spotify","seek":1,"duration":242,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 26 12:13:10 volumio-pi volumio[8433]: verbose: CURRENT POSITION 0 Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::syncState stateService pause Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::syncState currentStatus stop Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:13:10 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:10 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:10+02:00" level=trace msg="emitting websocket event: playing" Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","play_origin":"go-librespot"}} Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","service":"spop","title":"Sortedam","artist":"Thomas Helmig","album":"Sortedam","albumart":"https://i.scdn.co/image/ab67616d00001e022be877f4dc9c12e6dacd72ad","uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","trackType":"spotify","seek":1,"duration":242,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreCommandRouter::servicePushState Oct 26 12:13:10 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:10 volumio-pi volumio[8433]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sortedam","artist":"Thomas Helmig","album":"Sortedam","albumart":"https://i.scdn.co/image/ab67616d00001e022be877f4dc9c12e6dacd72ad","uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","trackType":"spotify","seek":1,"duration":242,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 26 12:13:10 volumio-pi volumio[8433]: verbose: CURRENT POSITION 0 Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::syncState stateService play Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::syncState currentStatus stop Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","service":"spop","title":"Sortedam","artist":"Thomas Helmig","album":"Sortedam","albumart":"https://i.scdn.co/image/ab67616d00001e022be877f4dc9c12e6dacd72ad","uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","trackType":"spotify","seek":1,"duration":242,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreCommandRouter::servicePushState Oct 26 12:13:10 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:10 volumio-pi volumio[8433]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Sortedam","artist":"Thomas Helmig","album":"Sortedam","albumart":"https://i.scdn.co/image/ab67616d00001e022be877f4dc9c12e6dacd72ad","uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","trackType":"spotify","seek":1,"duration":242,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 26 12:13:10 volumio-pi volumio[8433]: verbose: CURRENT POSITION 0 Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::syncState stateService play Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::syncState currentStatus play Oct 26 12:13:10 volumio-pi volumio[8433]: info: Received an update from plugin. extracting info from payload Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:13:10 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:13:10 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:10 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:10 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:13 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:13+02:00" level=debug msg="handling play player command from d4ddc4a8c15b2baedda9b3788de565d7515d63ed" Oct 26 12:13:13 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:13+02:00" level=debug msg="resolved context of track" uri="spotify:album:14EWYgtvXZSz0pzvpUCsbL" Oct 26 12:13:13 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:13+02:00" level=trace msg="fetched new page 0 with 64 items (list: 64)" uri="spotify:album:14EWYgtvXZSz0pzvpUCsbL" Oct 26 12:13:13 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:13+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:13 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:13 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:13+02:00" level=trace msg="emitting websocket event: will_play" Oct 26 12:13:13 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5TDdpLQhHj8LnFt4E0UDM0","play_origin":"album"}} Oct 26 12:13:13 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:13+02:00" level=debug msg="selected format OGG_VORBIS_320 (2a55e853e4cd2362222bc452d7cdec90f1529ffa)" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:13 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:13+02:00" level=debug msg="requested aes key for file 2a55e853e4cd2362222bc452d7cdec90f1529ffa, gid: 5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:14 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 26 12:13:14 volumio-pi volumio[8433]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 26 12:13:14 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:14 volumio-pi volumio[8433]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=debug msg="fetched first chunk of 61, total size is 31953021 bytes" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=info msg="loaded track \"Once Upon A Time In The West - Live At Hammersmith Odeon, London / 1983 / Remastered 2023\" (paused: false, position: 0ms, duration: 767773ms, prefetched: false)" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=debug msg="fetched chunk 1/60, size: 524288" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=debug msg="fetched chunk 2/60, size: 524288" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=trace msg="scheduling prefetch in 737s" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=trace msg="emitting websocket event: metadata" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=debug msg="sending successful reply for dealer request" Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5TDdpLQhHj8LnFt4E0UDM0","name":"Once Upon A Time In The West - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist_names":["Dire Straits"],"album_name":"Live 1978 - 1992","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","position":0,"duration":767773,"release_date":"year:2023 month:11 day:3","track_number":1,"disc_number":1}} Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=debug msg="fetched chunk 3/60, size: 524288" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:15 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:15+02:00" level=trace msg="emitting websocket event: playing" Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5TDdpLQhHj8LnFt4E0UDM0","play_origin":"album"}} Oct 26 12:13:15 volumio-pi volumio[8433]: info: Spotify is playing in volatile mode Oct 26 12:13:15 volumio-pi volumio[8433]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: UNSET VOLATILE Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","position":0,"title":"Sortedam","artist":"Thomas Helmig","album":"Sortedam","albumart":"https://i.scdn.co/image/ab67616d0000b2732be877f4dc9c12e6dacd72ad","uri":"spotify:track:3KKfy9c7s81AOoXbqd1obP","trackType":"spotify","codec":"ogg","seek":1,"duration":242,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"} Oct 26 12:13:15 volumio-pi volumio[8433]: info: Setting Spotify stop after unset volatile call Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","service":"spop","title":"Once Upon A Time In The West - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist":"Dire Straits","album":"Live 1978 - 1992","albumart":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","uri":"spotify:track:5TDdpLQhHj8LnFt4E0UDM0","trackType":"spotify","seek":0,"duration":767,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 26 12:13:15 volumio-pi volumio[8433]: info: CoreCommandRouter::servicePushState Oct 26 12:13:15 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:13:15 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:15 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: PUSH STATE SPOTIFY Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","service":"spop","title":"Once Upon A Time In The West - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist":"Dire Straits","album":"Live 1978 - 1992","albumart":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","uri":"spotify:track:5TDdpLQhHj8LnFt4E0UDM0","trackType":"spotify","seek":0,"duration":767,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 26 12:13:15 volumio-pi volumio[8433]: info: CoreCommandRouter::servicePushState Oct 26 12:13:15 volumio-pi volumio[8433]: info: CoreStateMachine::pushState Oct 26 12:13:15 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:15 volumio-pi volumio[8433]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Oct 26 12:13:16 volumio-pi volumio[8433]: info: Spotify Stop Oct 26 12:13:16 volumio-pi volumio[8433]: SPOTIFY: SPOTIFY STOP Oct 26 12:13:16 volumio-pi volumio[8433]: SPOTIFY: {"status":"play","title":"Once Upon A Time In The West - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist":"Dire Straits","album":"Live 1978 - 1992","albumart":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","uri":"spotify:track:5TDdpLQhHj8LnFt4E0UDM0","trackType":"spotify","codec":"ogg","seek":0,"duration":767,"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,"volatile":true,"service":"spop"} Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::volumioGetBrowseSources Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 12:13:19 volumio-pi volumio-remote-updater[635]: No test mode Oct 26 12:13:19 volumio-pi volumio-remote-updater[635]: No alpha test mode Oct 26 12:13:19 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 26 12:13:20 volumio-pi volumio[8433]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 26 12:13:20 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 26 12:13:20 volumio-pi volumio[8433]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 26 12:13:20 volumio-pi volumio[8433]: info: Completed starting MyVolumio Plugin Oct 26 12:13:20 volumio-pi volumio[8433]: info: BOOT COMPLETED Oct 26 12:13:20 volumio-pi volumio[8433]: [Metrics] CommandRouter: 34s 759.81ms Oct 26 12:13:20 volumio-pi volumio[8433]: info: CoreCommandRouter::volumiosetStartupVolume Oct 26 12:13:20 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:20 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:20 volumio-pi volumio[8433]: info: CoreCommandRouter::Close All Modals sent Oct 26 12:13:20 volumio-pi volumio[8433]: info: CoreCommandRouter::Close All Modals sent Oct 26 12:13:20 volumio-pi volumio[8433]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Oct 26 12:13:20 volumio-pi volumio[8433]: aplay: main:828: audio open error: Device or resource busy Oct 26 12:13:21 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 26 12:13:21 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 26 12:13:21 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 26 12:13:23 volumio-pi volumio[8433]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 26 12:13:23 volumio-pi volumio[8433]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 12:13:23 volumio-pi volumio[8433]: TypeError: Cannot read property 'length' of undefined Oct 26 12:13:23 volumio-pi volumio[8433]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Oct 26 12:13:23 volumio-pi volumio[8433]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Oct 26 12:13:23 volumio-pi volumio[8433]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Oct 26 12:13:23 volumio-pi volumio[8433]: at Parser.emit (events.js:315:20) Oct 26 12:13:23 volumio-pi volumio[8433]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Oct 26 12:13:23 volumio-pi volumio[8433]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Oct 26 12:13:23 volumio-pi volumio[8433]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Oct 26 12:13:23 volumio-pi volumio[8433]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Oct 26 12:13:23 volumio-pi volumio[8433]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Oct 26 12:13:23 volumio-pi volumio[8433]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Oct 26 12:13:23 volumio-pi volumio[8433]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Oct 26 12:13:23 volumio-pi volumio[8433]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Oct 26 12:13:23 volumio-pi volumio[8433]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Oct 26 12:13:23 volumio-pi volumio[8433]: at IncomingMessage.emit (events.js:327:22) Oct 26 12:13:23 volumio-pi volumio[8433]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 26 12:13:23 volumio-pi volumio[8433]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 26 12:13:23 volumio-pi volumio[8433]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 12:13:23 volumio-pi sudo[8702]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-26 12:12 Oct 26 12:13:23 volumio-pi sudo[8702]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:23 volumio-pi sudo[8702]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:23 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:13:23] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 26 12:13:23 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:13:23] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 26 12:13:23 volumio-pi systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 26 12:13:23 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:23+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Oct 26 12:13:23 volumio-pi systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 26 12:13:23 volumio-pi systemd[1]: Started dynamicswap service. Oct 26 12:13:23 volumio-pi systemd[1]: dynamicswap.service: Succeeded. Oct 26 12:13:23 volumio-pi systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 26 12:13:23 volumio-pi systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2. Oct 26 12:13:23 volumio-pi systemd[1]: Started dynamicswap service. Oct 26 12:13:23 volumio-pi systemd[1]: Stopped Volumio Backend Module. Oct 26 12:13:23 volumio-pi systemd[1]: Started Volumio Backend Module. Oct 26 12:13:23 volumio-pi systemd[1]: dynamicswap.service: Succeeded. Oct 26 12:13:24 volumio-pi volumio[8714]: info: ------------------------------------------- Oct 26 12:13:24 volumio-pi volumio[8714]: info: ----- Volumio3 ---- Oct 26 12:13:24 volumio-pi volumio[8714]: info: ------------------------------------------- Oct 26 12:13:24 volumio-pi volumio[8714]: info: ----- System startup ---- Oct 26 12:13:24 volumio-pi volumio[8714]: info: ------------------------------------------- Oct 26 12:13:25 volumio-pi volumio[8714]: info: MYVOLUMIO Environment detected Oct 26 12:13:25 volumio-pi volumio[8714]: info: Plugin folders cleanup Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning into folder /volumio/app/plugins/ Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning category audio_interface Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning category miscellanea Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning category music_service Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning category plugins.json Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning category system_controller Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning category user_interface Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning into folder /data/plugins/ Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning category music_service Oct 26 12:13:25 volumio-pi volumio[8714]: info: Scanning category system_controller Oct 26 12:13:25 volumio-pi volumio[8714]: info: Plugin folders cleanup completed Oct 26 12:13:25 volumio-pi volumio[8714]: info: ------------------------------------------- Oct 26 12:13:25 volumio-pi volumio[8714]: info: ----- Core plugins startup ---- Oct 26 12:13:25 volumio-pi volumio[8714]: info: ------------------------------------------- Oct 26 12:13:25 volumio-pi volumio[8714]: info: Loading plugins from folder /volumio/app/plugins/ Oct 26 12:13:25 volumio-pi volumio[8714]: info: Adding plugin upnp to MyMusic Plugins Oct 26 12:13:25 volumio-pi volumio[8714]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 26 12:13:25 volumio-pi volumio[8714]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 26 12:13:25 volumio-pi volumio[8714]: info: Loading plugins from folder /data/plugins/ Oct 26 12:13:25 volumio-pi volumio[8714]: info: Loading plugin "system"... Oct 26 12:13:25 volumio-pi volumio[8714]: info: Loading plugin "appearance"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "network"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Refreshing Cached IP Addresses Oct 26 12:13:26 volumio-pi sudo[8741]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 12:13:26 volumio-pi sudo[8741]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:26 volumio-pi sudo[8741]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:26 volumio-pi sudo[8743]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "services"... Oct 26 12:13:26 volumio-pi sudo[8743]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "alsa_controller"... Oct 26 12:13:26 volumio-pi sudo[8743]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:26 volumio-pi sudo[8746]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 26 12:13:26 volumio-pi sudo[8746]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:26 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "wizard"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "networkfs"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Starting Udev Watcher for removable devices Oct 26 12:13:26 volumio-pi volumio[8714]: info: Ignoring mount for partition: boot Oct 26 12:13:26 volumio-pi volumio[8714]: info: Ignoring mount for partition: volumio Oct 26 12:13:26 volumio-pi volumio[8714]: info: Ignoring mount for partition: volumio_data Oct 26 12:13:26 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "volumio_command_line_client"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "upnp"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: [1729937606191] Starting Upmpd Daemon Oct 26 12:13:26 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "my_music"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "mpd"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "upnp_browser"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "alarm-clock"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "airplay_emulation"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Starting Shairport Sync Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "last_100"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "webradio"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "i2s_dacs"... Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "volumiodiscovery"... Oct 26 12:13:26 volumio-pi volumio[8714]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 12:13:26 volumio-pi volumio[8714]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:13:26 volumio-pi node[8714]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 12:13:26 volumio-pi volumio[8714]: *** WARNING *** For more information see Oct 26 12:13:26 volumio-pi volumio[8714]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 12:13:26 volumio-pi volumio[8714]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:13:26 volumio-pi volumio[8714]: *** WARNING *** For more information see Oct 26 12:13:26 volumio-pi node[8714]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:13:26 volumio-pi node[8714]: *** WARNING *** For more information see Oct 26 12:13:26 volumio-pi node[8714]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 12:13:26 volumio-pi node[8714]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:13:26 volumio-pi node[8714]: *** WARNING *** For more information see Oct 26 12:13:26 volumio-pi volumio[8714]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 26 12:13:26 volumio-pi volumio[8714]: info: Discovery: Started advertising with name: Volumio PI Oct 26 12:13:26 volumio-pi go-librespot[8590]: time="2024-10-26T12:13:26+02:00" level=debug msg="fetched chunk 4/60, size: 524288" uri="spotify:track:5TDdpLQhHj8LnFt4E0UDM0" Oct 26 12:13:26 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:13:26 volumio-pi volumio[8714]: info: Loading plugin "spop"... Oct 26 12:13:27 volumio-pi volumio[8714]: info: Loading plugin "autostart"... Oct 26 12:13:27 volumio-pi volumio[8714]: info: Applying required configuration parameters for plugin autostart Oct 26 12:13:27 volumio-pi volumio[8714]: info: AutoStart - onVolumioStart - read config.json Oct 26 12:13:27 volumio-pi volumio[8714]: info: Loading plugin "outputs"... Oct 26 12:13:27 volumio-pi volumio[8714]: info: Loading plugin "albumart"... Oct 26 12:13:27 volumio-pi volumio[8714]: info: Plugin example_plugin is not enabled Oct 26 12:13:27 volumio-pi volumio[8714]: info: Loading plugin "inputs"... Oct 26 12:13:27 volumio-pi volumio[8714]: info: Loading plugin "updater_comm"... Oct 26 12:13:27 volumio-pi volumio[8714]: info: Plugin mpdemulation is not enabled Oct 26 12:13:27 volumio-pi volumio[8714]: info: Loading plugin "rest_api"... Oct 26 12:13:27 volumio-pi volumio[8714]: info: Loading plugin "websocket"... Oct 26 12:13:27 volumio-pi volumio[8714]: info: Starting Socket.io Server version 2.3.0 Oct 26 12:13:27 volumio-pi volumio[8714]: info: Loading i18n strings for locale da Oct 26 12:13:27 volumio-pi volumio[8714]: Updating browse sources language Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:27 volumio-pi volumio[8714]: Forking 3 albumart workers Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::initPlayerControls Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:13:27 volumio-pi volumio[8714]: Express server listening on port 3000 Oct 26 12:13:27 volumio-pi volumio[8714]: [Metrics] WebUI: 3s 367.63ms Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreStateMachine::resetVolumioState Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreStateMachine::getcurrentVolume Oct 26 12:13:27 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 12:13:28 volumio-pi volumio[8714]: verbose: New Socket.io Connection to 192.168.50.211 from 192.168.50.139 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Edg/130.0.0.0 Engine version: 3 Transport: polling Total Clients: 1 Oct 26 12:13:28 volumio-pi volumio[8714]: verbose: New Socket.io Connection to 192.168.50.211 from 192.168.50.139 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Edg/130.0.0.0 Engine version: 3 Transport: polling Total Clients: 2 Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:28 volumio-pi volumio[8714]: info: Executing start script for DAC IQaudIO DAC Plus Oct 26 12:13:28 volumio-pi volumio[8714]: info: Reloading queue from file Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreStateMachine::setRepeat null single undefined Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreStateMachine::pushState Oct 26 12:13:28 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreStateMachine::setRandom null Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreStateMachine::pushState Oct 26 12:13:28 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:28 volumio-pi volumio[8714]: info: VolumeController:: Volume=100 Mute =false Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreStateMachine::pushState Oct 26 12:13:28 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreStateMachine::updateTrackBlock Oct 26 12:13:28 volumio-pi volumio[8714]: info: CorePlayQueue::getTrackBlock Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 12:13:28 volumio-pi volumio[8714]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 26 12:13:28 volumio-pi volumio[8714]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03111 Oct 26 12:13:28 volumio-pi volumio[8714]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 26 12:13:28 volumio-pi volumio[8714]: info: DAC script executed Oct 26 12:13:28 volumio-pi volumio[8714]: info: Setting Device type: Raspberry PI Oct 26 12:13:28 volumio-pi volumio[8714]: info: Completed loading Core Plugins Oct 26 12:13:28 volumio-pi volumio[8714]: info: Preparing to generate the ALSA configuration file Oct 26 12:13:28 volumio-pi volumio[8714]: info: Asound.conf file unchanged, so no further update is needed Oct 26 12:13:28 volumio-pi volumio[8714]: info: Output device has changed, restarting MPD Oct 26 12:13:28 volumio-pi volumio[8714]: info: Output device has changed, restarting Shairport Sync Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:28 volumio-pi sudo[8803]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 12:13:28 volumio-pi sudo[8803]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:28 volumio-pi sudo[8801]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 12:13:28 volumio-pi sudo[8801]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:28 volumio-pi systemd[1]: Stopping Music Player Daemon... Oct 26 12:13:28 volumio-pi systemd[1]: mpd.service: Succeeded. Oct 26 12:13:28 volumio-pi systemd[1]: Stopped Music Player Daemon. Oct 26 12:13:28 volumio-pi volumio[8714]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:13:28 volumio-pi volumio[8714]: info: ___________ START PLUGINS ___________ Oct 26 12:13:28 volumio-pi sudo[8801]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:28 volumio-pi volumio[8714]: info: ControllerMpd::onStart: Initializing MPD Oct 26 12:13:28 volumio-pi volumio[8714]: info: Creating MPD Configuration file Oct 26 12:13:28 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:13:28] [connect] Successful connection Oct 26 12:13:28 volumio-pi volumio[8714]: Starting albumart workers Oct 26 12:13:28 volumio-pi sudo[8810]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 12:13:28 volumio-pi systemd[1]: Starting Music Player Daemon... Oct 26 12:13:28 volumio-pi sudo[8810]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:28 volumio-pi sudo[8810]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:13:28 volumio-pi volumio[8714]: info: [1729937608575] CoreMusicLibrary::Adding element Medieservere Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:28 volumio-pi sudo[8813]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 12:13:28 volumio-pi sudo[8813]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:28 volumio-pi volumio[8714]: Starting albumart workers Oct 26 12:13:28 volumio-pi sudo[8808]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 12:13:28 volumio-pi sudo[8808]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:28 volumio-pi sudo[8808]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:28 volumio-pi volumio[8714]: Starting albumart workers Oct 26 12:13:28 volumio-pi systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 26 12:13:28 volumio-pi systemd[1]: mpd.service: Succeeded. Oct 26 12:13:28 volumio-pi systemd[1]: Stopped Music Player Daemon. Oct 26 12:13:28 volumio-pi volumio[8714]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:28 volumio-pi systemd[1]: Starting Music Player Daemon... Oct 26 12:13:28 volumio-pi sudo[8817]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 12:13:28 volumio-pi sudo[8817]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:28 volumio-pi sudo[8817]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:28 volumio-pi volumio[8714]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:13:28 volumio-pi volumio[8714]: info: [1729937608825] CoreMusicLibrary::Adding element Last_100 Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:13:28 volumio-pi volumio[8714]: info: [1729937608828] CoreMusicLibrary::Adding element Webradio Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:13:28 volumio-pi volumio[8714]: info: Initializing BBC Radios Oct 26 12:13:28 volumio-pi sudo[8746]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:13:28 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: Creating Spotify config file Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: AutoStart - onStart Oct 26 12:13:29 volumio-pi volumio[8714]: info: Volumio Calling Home Oct 26 12:13:29 volumio-pi volumio[8714]: info: MPD Permissions set Oct 26 12:13:29 volumio-pi volumio[8714]: info: MPD Permissions set Oct 26 12:13:29 volumio-pi volumio[8714]: info: VolumeController:: Volume=100 Mute =false Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreStateMachine::pushState Oct 26 12:13:29 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:29 volumio-pi volumio[8714]: info: Discovery: adding b37ff9d2-5853-457e-9dc0-bdd64172c9b7 Oct 26 12:13:29 volumio-pi volumio[8714]: info: Discovery: Found device Volumio PI Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:29 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:29 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:13:29] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1729937608 101 Oct 26 12:13:29 volumio-pi volumio[8714]: 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: 3 Oct 26 12:13:29 volumio-pi volumio[8714]: info: Volumio called home Oct 26 12:13:29 volumio-pi volumio[8714]: info: Spotify config file written Oct 26 12:13:29 volumio-pi sudo[8863]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 26 12:13:29 volumio-pi sudo[8863]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:29 volumio-pi volumio[8714]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi systemd[1]: Stopping go-librespot Daemon... Oct 26 12:13:29 volumio-pi systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 26 12:13:29 volumio-pi systemd[1]: go-librespot-daemon.service: Succeeded. Oct 26 12:13:29 volumio-pi systemd[1]: Stopped go-librespot Daemon. Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:29 volumio-pi systemd[1]: Started go-librespot Daemon. Oct 26 12:13:29 volumio-pi volumio[8714]: info: No need to fix Spotify hosts Oct 26 12:13:29 volumio-pi go-librespot[8865]: Librespot-go daemon starting... Oct 26 12:13:29 volumio-pi sudo[8863]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=info msg="generated new device id: 5f7bf37b77070c836929f0a354f82b99ad34cfd1" Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=debug msg="stored credentials found for 313le7g4thoej6cykmoa3argwfme" Oct 26 12:13:29 volumio-pi volumio[8714]: info: Starting Shairport Sync Oct 26 12:13:29 volumio-pi volumio[8714]: info: Starting Shairport Sync Oct 26 12:13:29 volumio-pi volumio[8714]: info: Starting Shairport Sync Oct 26 12:13:29 volumio-pi sudo[8881]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:13:29 volumio-pi sudo[8881]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:29 volumio-pi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 12:13:29 volumio-pi systemd[1]: shairport-sync.service: Succeeded. Oct 26 12:13:29 volumio-pi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 12:13:29 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:29 volumio-pi sudo[8886]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:13:29 volumio-pi sudo[8887]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=debug msg="zeroconf server listening on port 40909" Oct 26 12:13:29 volumio-pi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 12:13:29 volumio-pi sudo[8886]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:29 volumio-pi sudo[8887]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:29 volumio-pi sudo[8881]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:29 volumio-pi volumio[8714]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 12:13:29 volumio-pi volumio[8714]: SPOTIFY: BQDpG85p7sH73gdYmCBx9ghnc9ymRH8LfqP_OOXK9GpRD84HMccC08P4SG2-DsM2f12IIYnstiXMukoK6F0gtPDJmKA0y_5rO-TIxq9dR_ujnqzTcAhTW6W453w2ucRHdmisVziAmkfigwYw0XISFAZGudwcLDQwnoxfBS2fVnE_vlQAREnat0y0AUyuUMxJ29CwIlMjTfuwwBgHOG35xrjFFamJjJ5WvfR60-u8gnA-aasRR1wztoCECqRExhTCOoqy9IxUYsVvkZ06eTU Oct 26 12:13:29 volumio-pi volumio[8714]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 12:13:29 volumio-pi volumio[8714]: info: New Spotify access token = BQDpG85p7sH73gdYmCBx9ghnc9ymRH8LfqP_OOXK9GpRD84HMccC08P4SG2-DsM2f12IIYnstiXMukoK6F0gtPDJmKA0y_5rO-TIxq9dR_ujnqzTcAhTW6W453w2ucRHdmisVziAmkfigwYw0XISFAZGudwcLDQwnoxfBS2fVnE_vlQAREnat0y0AUyuUMxJ29CwIlMjTfuwwBgHOG35xrjFFamJjJ5WvfR60-u8gnA-aasRR1wztoCECqRExhTCOoqy9IxUYsVvkZ06eTU Oct 26 12:13:29 volumio-pi volumio[8714]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 26 12:13:29 volumio-pi volumio[8714]: info: Shairport-Sync Started Oct 26 12:13:29 volumio-pi volumio[8714]: Error adding Membership: Error: addMembership EINVAL Oct 26 12:13:29 volumio-pi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 12:13:29 volumio-pi systemd[1]: shairport-sync.service: Succeeded. Oct 26 12:13:29 volumio-pi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=debug msg="obtained new client token: AAAbaQVsLQ4MOeOq6tOePuQzu6Zf5qiZlQFAnhwshmr7nmhrmW/nyQnfzFhB7Wu0q676Id1yCbGKh8zHe6aXk5XTNkKwOaT+1KXNFo3J7FXFyhaA+cG/dyyGJ41XxYjJi3+yesOvadXyEeFGe0bP1GWMnaTiGVoEjvKW23Ggu4NRWuT1V83OO85icDvhwLa5dkrBRDwE0msn6VP61gIljZX3xBQeEj/E6uaAKuMg1KmW0e/fhdw7yg1c8bUi/w==" Oct 26 12:13:29 volumio-pi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 12:13:29 volumio-pi sudo[8886]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:29 volumio-pi sudo[8887]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:29 volumio-pi volumio[8714]: info: Shairport-Sync Started Oct 26 12:13:29 volumio-pi volumio[8714]: info: Shairport-Sync Started Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Oct 26 12:13:29 volumio-pi mpd[8824]: Oct 26 12:13 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 26 12:13:29 volumio-pi systemd[1]: Started Music Player Daemon. Oct 26 12:13:29 volumio-pi sudo[8813]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:29 volumio-pi sudo[8803]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:29 volumio-pi volumio[8714]: info: Completed starting Core Plugins Oct 26 12:13:29 volumio-pi volumio[8714]: info: ------------------------------------------- Oct 26 12:13:29 volumio-pi volumio[8714]: info: ----- MyVolumio plugins startup ---- Oct 26 12:13:29 volumio-pi volumio[8714]: info: ------------------------------------------- Oct 26 12:13:29 volumio-pi volumio[8714]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 26 12:13:29 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:29+02:00" level=debug msg="completed keyexchange" Oct 26 12:13:29 volumio-pi volumio[8714]: error: MPD error: The expression evaluated to a falsy value: Oct 26 12:13:29 volumio-pi volumio[8714]: assert.ok(self.idling) Oct 26 12:13:29 volumio-pi volumio[8714]: error: The expression evaluated to a falsy value: Oct 26 12:13:29 volumio-pi volumio[8714]: assert.ok(self.idling) Oct 26 12:13:29 volumio-pi volumio[8714]: info: MPD running with PID8824 Oct 26 12:13:29 volumio-pi volumio[8714]: ,establishing connection Oct 26 12:13:29 volumio-pi volumio[8714]: error: MPD error: The expression evaluated to a falsy value: Oct 26 12:13:29 volumio-pi volumio[8714]: assert.ok(self.idling) Oct 26 12:13:29 volumio-pi volumio[8714]: error: The expression evaluated to a falsy value: Oct 26 12:13:29 volumio-pi volumio[8714]: assert.ok(self.idling) Oct 26 12:13:29 volumio-pi volumio[8714]: error: updateQueue error: null Oct 26 12:13:29 volumio-pi volumio[8714]: SPOTIFY: User informations: {"country":"DK","display_name":"Carsten","email":"carstenbfrederiksen@outlook.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/313le7g4thoej6cykmoa3argwfme"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/313le7g4thoej6cykmoa3argwfme","id":"313le7g4thoej6cykmoa3argwfme","images":[],"product":"premium","type":"user","uri":"spotify:user:313le7g4thoej6cykmoa3argwfme"} Oct 26 12:13:29 volumio-pi volumio[8714]: info: Spotify Successfully logged in Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:13:29 volumio-pi volumio[8714]: info: [1729937609986] CoreMusicLibrary::Adding element Spotify Oct 26 12:13:29 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:29 volumio-pi volumio[8714]: Cannot find translation for source Spotify Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="completed challenge" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="authenticated as 313le7g4thoej6cykmoa3argwfme" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="authenticated as 313le7g4thoej6cykmoa3argwfme" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="dealer connection opened" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="initializing zeroconf session, username: 313le7g4thoej6cykmoa3argwfme" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="autoplay enabled: false" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="received connection id: NTkwZDE0NjUtMDI2My00NjhkLWFmMTUtNDVhMDE1MTZmMDAyK2RlYWxlcit0Y3A6Ly8wYWNhNThmNC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArOTY2QjJFQ0REN0FGMDAwRUEyMTJDNjM3ODM1NTI0REE3QTdCMzU4NjRCRkZDNjg0MTk1RjBBNTc0RUM1Q0NCNg==" Oct 26 12:13:30 volumio-pi go-librespot[8865]: time="2024-10-26T12:13:30+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 26 12:13:32 volumio-pi volumio[8714]: verbose: New Socket.io Connection to 192.168.50.211 from 192.168.50.139 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Edg/130.0.0.0 Engine version: 3 Transport: polling Total Clients: 5 Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioGetVisibleSources Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:32 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:32 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 26 12:13:32 volumio-pi volumio[8714]: info: Received Get System Info Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 26 12:13:32 volumio-pi volumio[8714]: info: Discovery: Getting this device information Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:32 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:32 volumio-pi volumio[8714]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:32 volumio-pi volumio[8714]: info: Listing playlists Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreCommandRouter::volumioGetQueue Oct 26 12:13:32 volumio-pi volumio[8714]: info: CoreStateMachine::getQueue Oct 26 12:13:32 volumio-pi volumio[8714]: info: CorePlayQueue::getQueue Oct 26 12:13:32 volumio-pi volumio[8714]: info: go-librespot daemon successfully initialized Oct 26 12:13:33 volumio-pi volumio[8714]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Oct 26 12:13:33 volumio-pi volumio[8714]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 12:13:33 volumio-pi volumio[8714]: TypeError: Cannot read property 'length' of undefined Oct 26 12:13:33 volumio-pi volumio[8714]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Oct 26 12:13:33 volumio-pi volumio[8714]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Oct 26 12:13:33 volumio-pi volumio[8714]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Oct 26 12:13:33 volumio-pi volumio[8714]: at Parser.emit (events.js:315:20) Oct 26 12:13:33 volumio-pi volumio[8714]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Oct 26 12:13:33 volumio-pi volumio[8714]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Oct 26 12:13:33 volumio-pi volumio[8714]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Oct 26 12:13:33 volumio-pi volumio[8714]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Oct 26 12:13:33 volumio-pi volumio[8714]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Oct 26 12:13:33 volumio-pi volumio[8714]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Oct 26 12:13:33 volumio-pi volumio[8714]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Oct 26 12:13:33 volumio-pi volumio[8714]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Oct 26 12:13:33 volumio-pi volumio[8714]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Oct 26 12:13:33 volumio-pi volumio[8714]: at IncomingMessage.emit (events.js:327:22) Oct 26 12:13:33 volumio-pi volumio[8714]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 26 12:13:33 volumio-pi volumio[8714]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 26 12:13:33 volumio-pi volumio[8714]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 12:13:34 volumio-pi sudo[8910]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-26 12:12 Oct 26 12:13:34 volumio-pi sudo[8910]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:34 volumio-pi sudo[8910]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:34 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:13:34] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 26 12:13:34 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:13:34] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 26 12:13:34 volumio-pi systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 26 12:13:34 volumio-pi systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 26 12:13:34 volumio-pi systemd[1]: Started dynamicswap service. Oct 26 12:13:34 volumio-pi systemd[1]: dynamicswap.service: Succeeded. Oct 26 12:13:34 volumio-pi systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 26 12:13:34 volumio-pi systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3. Oct 26 12:13:34 volumio-pi systemd[1]: Stopped Volumio Backend Module. Oct 26 12:13:34 volumio-pi systemd[1]: Started Volumio Backend Module. Oct 26 12:13:34 volumio-pi systemd[1]: Started dynamicswap service. Oct 26 12:13:34 volumio-pi systemd[1]: dynamicswap.service: Succeeded. Oct 26 12:13:35 volumio-pi volumio[8920]: info: ------------------------------------------- Oct 26 12:13:35 volumio-pi volumio[8920]: info: ----- Volumio3 ---- Oct 26 12:13:35 volumio-pi volumio[8920]: info: ------------------------------------------- Oct 26 12:13:35 volumio-pi volumio[8920]: info: ----- System startup ---- Oct 26 12:13:35 volumio-pi volumio[8920]: info: ------------------------------------------- Oct 26 12:13:35 volumio-pi volumio[8920]: info: MYVOLUMIO Environment detected Oct 26 12:13:36 volumio-pi volumio[8920]: info: Plugin folders cleanup Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning into folder /volumio/app/plugins/ Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning category audio_interface Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning category miscellanea Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning category music_service Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning category plugins.json Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning category system_controller Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning category user_interface Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning into folder /data/plugins/ Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning category music_service Oct 26 12:13:36 volumio-pi volumio[8920]: info: Scanning category system_controller Oct 26 12:13:36 volumio-pi volumio[8920]: info: Plugin folders cleanup completed Oct 26 12:13:36 volumio-pi volumio[8920]: info: ------------------------------------------- Oct 26 12:13:36 volumio-pi volumio[8920]: info: ----- Core plugins startup ---- Oct 26 12:13:36 volumio-pi volumio[8920]: info: ------------------------------------------- Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugins from folder /volumio/app/plugins/ Oct 26 12:13:36 volumio-pi volumio[8920]: info: Adding plugin upnp to MyMusic Plugins Oct 26 12:13:36 volumio-pi volumio[8920]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 26 12:13:36 volumio-pi volumio[8920]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugins from folder /data/plugins/ Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "system"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "appearance"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "network"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Refreshing Cached IP Addresses Oct 26 12:13:36 volumio-pi sudo[8947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 12:13:36 volumio-pi sudo[8947]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:36 volumio-pi sudo[8947]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:36 volumio-pi sudo[8949]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 12:13:36 volumio-pi sudo[8949]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "services"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "alsa_controller"... Oct 26 12:13:36 volumio-pi sudo[8949]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:36 volumio-pi sudo[8953]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 26 12:13:36 volumio-pi sudo[8953]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:36 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "wizard"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "networkfs"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Starting Udev Watcher for removable devices Oct 26 12:13:36 volumio-pi volumio[8920]: info: Ignoring mount for partition: boot Oct 26 12:13:36 volumio-pi volumio[8920]: info: Ignoring mount for partition: volumio Oct 26 12:13:36 volumio-pi volumio[8920]: info: Ignoring mount for partition: volumio_data Oct 26 12:13:36 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "volumio_command_line_client"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "upnp"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: [1729937616782] Starting Upmpd Daemon Oct 26 12:13:36 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "my_music"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "mpd"... Oct 26 12:13:36 volumio-pi volumio[8920]: info: Loading plugin "upnp_browser"... Oct 26 12:13:37 volumio-pi volumio[8920]: info: Loading plugin "alarm-clock"... Oct 26 12:13:37 volumio-pi volumio[8920]: info: Loading plugin "airplay_emulation"... Oct 26 12:13:37 volumio-pi volumio[8920]: info: Starting Shairport Sync Oct 26 12:13:37 volumio-pi volumio[8920]: info: Loading plugin "last_100"... Oct 26 12:13:37 volumio-pi volumio[8920]: info: Loading plugin "webradio"... Oct 26 12:13:37 volumio-pi volumio[8920]: info: Loading plugin "i2s_dacs"... Oct 26 12:13:37 volumio-pi volumio[8920]: info: Loading plugin "volumiodiscovery"... Oct 26 12:13:37 volumio-pi volumio[8920]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 12:13:37 volumio-pi volumio[8920]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:13:37 volumio-pi node[8920]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 26 12:13:37 volumio-pi volumio[8920]: *** WARNING *** For more information see Oct 26 12:13:37 volumio-pi volumio[8920]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 12:13:37 volumio-pi volumio[8920]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:13:37 volumio-pi volumio[8920]: *** WARNING *** For more information see Oct 26 12:13:37 volumio-pi node[8920]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:13:37 volumio-pi node[8920]: *** WARNING *** For more information see Oct 26 12:13:37 volumio-pi node[8920]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 26 12:13:37 volumio-pi node[8920]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 26 12:13:37 volumio-pi node[8920]: *** WARNING *** For more information see Oct 26 12:13:37 volumio-pi volumio[8920]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 26 12:13:37 volumio-pi volumio[8920]: info: Discovery: Started advertising with name: Volumio PI Oct 26 12:13:37 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 26 12:13:37 volumio-pi volumio[8920]: info: Loading plugin "spop"... Oct 26 12:13:37 volumio-pi volumio[8920]: info: Loading plugin "autostart"... Oct 26 12:13:38 volumio-pi volumio[8920]: info: Applying required configuration parameters for plugin autostart Oct 26 12:13:38 volumio-pi volumio[8920]: info: AutoStart - onVolumioStart - read config.json Oct 26 12:13:38 volumio-pi volumio[8920]: info: Loading plugin "outputs"... Oct 26 12:13:38 volumio-pi volumio[8920]: info: Loading plugin "albumart"... Oct 26 12:13:38 volumio-pi volumio[8920]: info: Plugin example_plugin is not enabled Oct 26 12:13:38 volumio-pi volumio[8920]: info: Loading plugin "inputs"... Oct 26 12:13:38 volumio-pi volumio[8920]: info: Loading plugin "updater_comm"... Oct 26 12:13:38 volumio-pi volumio[8920]: info: Plugin mpdemulation is not enabled Oct 26 12:13:38 volumio-pi volumio[8920]: info: Loading plugin "rest_api"... Oct 26 12:13:38 volumio-pi volumio[8920]: info: Loading plugin "websocket"... Oct 26 12:13:38 volumio-pi volumio[8920]: info: Starting Socket.io Server version 2.3.0 Oct 26 12:13:38 volumio-pi volumio[8920]: info: Loading i18n strings for locale da Oct 26 12:13:38 volumio-pi volumio[8920]: Updating browse sources language Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::initPlayerControls Oct 26 12:13:38 volumio-pi volumio[8920]: Forking 3 albumart workers Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: Express server listening on port 3000 Oct 26 12:13:38 volumio-pi volumio[8920]: [Metrics] WebUI: 3s 129.20ms Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreStateMachine::resetVolumioState Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreStateMachine::getcurrentVolume Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 12:13:38 volumio-pi volumio[8920]: verbose: New Socket.io Connection to 192.168.50.211 from 192.168.50.139 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36 Edg/130.0.0.0 Engine version: 3 Transport: polling Total Clients: 1 Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: Executing start script for DAC IQaudIO DAC Plus Oct 26 12:13:38 volumio-pi volumio[8920]: info: Reloading queue from file Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreStateMachine::setRepeat null single undefined Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreStateMachine::pushState Oct 26 12:13:38 volumio-pi volumio[8920]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreStateMachine::setRandom null Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreStateMachine::pushState Oct 26 12:13:38 volumio-pi volumio[8920]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:38 volumio-pi volumio[8920]: info: Setting Device type: Raspberry PI Oct 26 12:13:38 volumio-pi volumio[8920]: info: VolumeController:: Volume=100 Mute =false Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreStateMachine::pushState Oct 26 12:13:38 volumio-pi volumio[8920]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreStateMachine::updateTrackBlock Oct 26 12:13:38 volumio-pi volumio[8920]: info: CorePlayQueue::getTrackBlock Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioRetrievevolume Oct 26 12:13:38 volumio-pi volumio[8920]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 26 12:13:38 volumio-pi volumio[8920]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03111 Oct 26 12:13:38 volumio-pi volumio[8920]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 26 12:13:38 volumio-pi volumio[8920]: info: DAC script executed Oct 26 12:13:38 volumio-pi volumio[8920]: info: Completed loading Core Plugins Oct 26 12:13:38 volumio-pi volumio[8920]: info: Preparing to generate the ALSA configuration file Oct 26 12:13:38 volumio-pi volumio[8920]: info: Asound.conf file unchanged, so no further update is needed Oct 26 12:13:38 volumio-pi volumio[8920]: info: Output device has changed, restarting MPD Oct 26 12:13:38 volumio-pi volumio[8920]: info: Output device has changed, restarting Shairport Sync Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:38 volumio-pi sudo[9006]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 12:13:38 volumio-pi sudo[9008]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 12:13:38 volumio-pi sudo[9008]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:38 volumio-pi sudo[9006]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:38 volumio-pi sudo[9006]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:38 volumio-pi systemd[1]: Stopping Music Player Daemon... Oct 26 12:13:38 volumio-pi systemd[1]: mpd.service: Succeeded. Oct 26 12:13:38 volumio-pi systemd[1]: Stopped Music Player Daemon. Oct 26 12:13:38 volumio-pi volumio[8920]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:13:38 volumio-pi volumio[8920]: info: ___________ START PLUGINS ___________ Oct 26 12:13:38 volumio-pi volumio[8920]: info: ControllerMpd::onStart: Initializing MPD Oct 26 12:13:38 volumio-pi volumio[8920]: info: Creating MPD Configuration file Oct 26 12:13:38 volumio-pi sudo[9015]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 26 12:13:38 volumio-pi sudo[9015]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:38 volumio-pi systemd[1]: Starting Music Player Daemon... Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:13:38 volumio-pi volumio[8920]: info: [1729937618952] CoreMusicLibrary::Adding element Medieservere Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:38 volumio-pi sudo[9015]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:38 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:38 volumio-pi sudo[9018]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 26 12:13:39 volumio-pi sudo[9018]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:39 volumio-pi volumio[8920]: Starting albumart workers Oct 26 12:13:39 volumio-pi systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 26 12:13:39 volumio-pi systemd[1]: mpd.service: Succeeded. Oct 26 12:13:39 volumio-pi systemd[1]: Stopped Music Player Daemon. Oct 26 12:13:39 volumio-pi systemd[1]: Starting Music Player Daemon... Oct 26 12:13:39 volumio-pi volumio[8920]: Starting albumart workers Oct 26 12:13:39 volumio-pi volumio[8920]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:39 volumio-pi sudo[9023]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 26 12:13:39 volumio-pi sudo[9023]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:39 volumio-pi sudo[9023]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:39 volumio-pi volumio[8920]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:13:39 volumio-pi volumio[8920]: info: [1729937619120] CoreMusicLibrary::Adding element Last_100 Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:13:39 volumio-pi volumio[8920]: info: [1729937619122] CoreMusicLibrary::Adding element Webradio Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:13:39 volumio-pi volumio[8920]: info: Initializing BBC Radios Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: Starting albumart workers Oct 26 12:13:39 volumio-pi volumio[8920]: info: Creating Spotify config file Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: AutoStart - onStart Oct 26 12:13:39 volumio-pi volumio[8920]: info: Volumio Calling Home Oct 26 12:13:39 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:13:39] [connect] Successful connection Oct 26 12:13:39 volumio-pi volumio[8920]: info: Discovery: adding b37ff9d2-5853-457e-9dc0-bdd64172c9b7 Oct 26 12:13:39 volumio-pi volumio[8920]: info: Discovery: Found device Volumio PI Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:39 volumio-pi volumio[8920]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:39 volumio-pi volumio[8920]: info: MPD Permissions set Oct 26 12:13:39 volumio-pi volumio[8920]: info: MPD Permissions set Oct 26 12:13:39 volumio-pi sudo[8953]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:39 volumio-pi volumio-remote-updater[635]: [2024-10-26 12:13:39] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1729937619 101 Oct 26 12:13:39 volumio-pi volumio[8920]: 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: 2 Oct 26 12:13:39 volumio-pi volumio[8920]: info: Spotify config file written Oct 26 12:13:39 volumio-pi volumio[8920]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 26 12:13:39 volumio-pi volumio[8920]: info: VolumeController:: Volume=100 Mute =false Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreStateMachine::pushState Oct 26 12:13:39 volumio-pi volumio[8920]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioPushState Oct 26 12:13:39 volumio-pi volumio[8920]: info: Volumio called home Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi sudo[9052]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi sudo[9052]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:39 volumio-pi systemd[1]: Stopping go-librespot Daemon... Oct 26 12:13:39 volumio-pi systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 26 12:13:39 volumio-pi systemd[1]: go-librespot-daemon.service: Succeeded. Oct 26 12:13:39 volumio-pi systemd[1]: Stopped go-librespot Daemon. Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi systemd[1]: Started go-librespot Daemon. Oct 26 12:13:39 volumio-pi go-librespot[9055]: Librespot-go daemon starting... Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 26 12:13:39 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 26 12:13:39 volumio-pi sudo[9052]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:39 volumio-pi volumio[8920]: info: No need to fix Spotify hosts Oct 26 12:13:39 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:39+02:00" level=info msg="generated new device id: 031f3994ec3e85a426951e44b4a53523fba265b1" Oct 26 12:13:39 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:39+02:00" level=debug msg="stored credentials found for 313le7g4thoej6cykmoa3argwfme" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="zeroconf server listening on port 45527" Oct 26 12:13:40 volumio-pi volumio[8920]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 12:13:40 volumio-pi volumio[8920]: SPOTIFY: BQCoSU1PHNAuCbmlI5yMnUVBuJc9zq2n-yrQsXOUZA5KwPJVkmoSIpAosXqZ1csTuMPh2EXK0Kt4zwk1K7CIhxKQClKD8IoIgkZKlYTqGRHslMkE5g8FE5q-ORAK_CxfFa5HzEfDNxNtE0oY_S8uy8PHgIS57Iw8gVDsga7eC56wLfOyFNApmAk3ShudRVAxZxndagp4x5uBRLI8sEOOxlxvS5SZUT4nTQveV6wJwhkckDWOPu2eQLVBw72z6_OKe0loyRGPVzeJhf_2njg Oct 26 12:13:40 volumio-pi volumio[8920]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 26 12:13:40 volumio-pi volumio[8920]: info: New Spotify access token = BQCoSU1PHNAuCbmlI5yMnUVBuJc9zq2n-yrQsXOUZA5KwPJVkmoSIpAosXqZ1csTuMPh2EXK0Kt4zwk1K7CIhxKQClKD8IoIgkZKlYTqGRHslMkE5g8FE5q-ORAK_CxfFa5HzEfDNxNtE0oY_S8uy8PHgIS57Iw8gVDsga7eC56wLfOyFNApmAk3ShudRVAxZxndagp4x5uBRLI8sEOOxlxvS5SZUT4nTQveV6wJwhkckDWOPu2eQLVBw72z6_OKe0loyRGPVzeJhf_2njg Oct 26 12:13:40 volumio-pi volumio[8920]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 26 12:13:40 volumio-pi volumio[8920]: info: Starting Shairport Sync Oct 26 12:13:40 volumio-pi volumio[8920]: info: Starting Shairport Sync Oct 26 12:13:40 volumio-pi sudo[9088]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:13:40 volumio-pi sudo[9088]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:40 volumio-pi volumio[8920]: info: Starting Shairport Sync Oct 26 12:13:40 volumio-pi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="obtained new client token: AADRSBSzTOXbGl8K9OZ9g8mCYsY/DltMhSoB9AEMj+rYWeFBlMDuSyP61sR/1g9hojz28H2WukEme6IHXWCDElbnLEU708CGIthoy53j27eO7pXg8LN8wTFEbJ8ox/OdCZiKYf7lXlwlfz7EoiiecU/rQvVMQ4+MFvvV0Uo0pdGva48I/vsaB6iZC2ZETwP8SkaaLpkhRtrNVSnGrmmUHO4FkMM9A3qKWam+Pk6wI8jyNmF5g3K8LudWRQU=" Oct 26 12:13:40 volumio-pi systemd[1]: shairport-sync.service: Succeeded. Oct 26 12:13:40 volumio-pi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 12:13:40 volumio-pi sudo[9091]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:13:40 volumio-pi sudo[9091]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:40 volumio-pi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 12:13:40 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:40 volumio-pi volumio[8920]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Oct 26 12:13:40 volumio-pi sudo[9095]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 26 12:13:40 volumio-pi sudo[9095]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:40 volumio-pi sudo[9088]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=info msg="connected to ap-gew4.spotify.com:443" Oct 26 12:13:40 volumio-pi volumio[8920]: info: Shairport-Sync Started Oct 26 12:13:40 volumio-pi volumio[8920]: Error adding Membership: Error: addMembership EINVAL Oct 26 12:13:40 volumio-pi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 26 12:13:40 volumio-pi systemd[1]: shairport-sync.service: Succeeded. Oct 26 12:13:40 volumio-pi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 26 12:13:40 volumio-pi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 26 12:13:40 volumio-pi sudo[9091]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="completed keyexchange" Oct 26 12:13:40 volumio-pi sudo[9095]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:40 volumio-pi mpd[9028]: Oct 26 12:13 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 26 12:13:40 volumio-pi volumio[8920]: info: Shairport-Sync Started Oct 26 12:13:40 volumio-pi volumio[8920]: info: Shairport-Sync Started Oct 26 12:13:40 volumio-pi systemd[1]: Started Music Player Daemon. Oct 26 12:13:40 volumio-pi sudo[9008]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:40 volumio-pi sudo[9018]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:40 volumio-pi volumio[8920]: SPOTIFY: User informations: {"country":"DK","display_name":"Carsten","email":"carstenbfrederiksen@outlook.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/313le7g4thoej6cykmoa3argwfme"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/313le7g4thoej6cykmoa3argwfme","id":"313le7g4thoej6cykmoa3argwfme","images":[],"product":"premium","type":"user","uri":"spotify:user:313le7g4thoej6cykmoa3argwfme"} Oct 26 12:13:40 volumio-pi volumio[8920]: info: Spotify Successfully logged in Oct 26 12:13:40 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 26 12:13:40 volumio-pi volumio[8920]: info: [1729937620253] CoreMusicLibrary::Adding element Spotify Oct 26 12:13:40 volumio-pi volumio[8920]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 26 12:13:40 volumio-pi volumio[8920]: Cannot find translation for source Spotify Oct 26 12:13:40 volumio-pi volumio[8920]: info: Completed starting Core Plugins Oct 26 12:13:40 volumio-pi volumio[8920]: info: ------------------------------------------- Oct 26 12:13:40 volumio-pi volumio[8920]: info: ----- MyVolumio plugins startup ---- Oct 26 12:13:40 volumio-pi volumio[8920]: info: ------------------------------------------- Oct 26 12:13:40 volumio-pi volumio[8920]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 26 12:13:40 volumio-pi volumio[8920]: error: MPD error: The expression evaluated to a falsy value: Oct 26 12:13:40 volumio-pi volumio[8920]: assert.ok(self.idling) Oct 26 12:13:40 volumio-pi volumio[8920]: error: The expression evaluated to a falsy value: Oct 26 12:13:40 volumio-pi volumio[8920]: assert.ok(self.idling) Oct 26 12:13:40 volumio-pi volumio[8920]: error: updateQueue error: null Oct 26 12:13:40 volumio-pi volumio[8920]: info: MPD running with PID9028 Oct 26 12:13:40 volumio-pi volumio[8920]: ,establishing connection Oct 26 12:13:40 volumio-pi volumio[8920]: error: updateQueue error: null Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="completed challenge" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="authenticated as 313le7g4thoej6cykmoa3argwfme" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="authenticated as 313le7g4thoej6cykmoa3argwfme" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="dealer connection opened" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="initializing zeroconf session, username: 313le7g4thoej6cykmoa3argwfme" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="autoplay enabled: false" Oct 26 12:13:40 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:40+02:00" level=debug msg="received connection id: M2Q4NTNjZDMtZGI2MS00MzU3LWFkNGYtZWNmNTFjNTUyN2E1K2RlYWxlcit0Y3A6Ly8wYWNhNTlkZS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMDNDODQxMzk1OThBQ0Q4RUEzM0M4REVERkEwN0VCOEYwNDc2QzRERTUwMDE1M0NGM0FFMUU1QThBMTYxREEyRQ==" Oct 26 12:13:41 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:41+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 26 12:13:41 volumio-pi volumiologrotate[614]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory Oct 26 12:13:41 volumio-pi volumiologrotate[614]: ls: cannot access 'PI': No such file or directory Oct 26 12:13:42 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:42+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 26 12:13:42 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:42+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Oct 26 12:13:42 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:42+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 26 12:13:42 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:42+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1457" Oct 26 12:13:43 volumio-pi volumio[8920]: info: go-librespot daemon successfully initialized Oct 26 12:13:45 volumio-pi volumio[8920]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 26 12:13:46 volumio-pi volumio[8920]: info: Initializing connection to go-librespot Websocket Oct 26 12:13:46 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:46+02:00" level=debug msg="new websocket client" Oct 26 12:13:46 volumio-pi volumio[8920]: info: Connection to go-librespot Websocket established Oct 26 12:13:46 volumio-pi sudo[9149]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 26 12:13:46 volumio-pi sudo[9149]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:46 volumio-pi sudo[9149]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:46 volumio-pi sudo[9151]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 26 12:13:46 volumio-pi sudo[9151]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:46 volumio-pi sudo[9151]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:46 volumio-pi sudo[9155]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 26 12:13:46 volumio-pi sudo[9155]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 26 12:13:46 volumio-pi sudo[9155]: pam_unix(sudo:session): session closed for user root Oct 26 12:13:46 volumio-pi volumio[8920]: info: Upmpdcli Daemon Started Oct 26 12:13:47 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:47+02:00" level=debug msg="handling transfer player command from d4ddc4a8c15b2baedda9b3788de565d7515d63ed" Oct 26 12:13:47 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:47+02:00" level=debug msg="resolved context of track" uri="spotify:album:14EWYgtvXZSz0pzvpUCsbL" Oct 26 12:13:47 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:47+02:00" level=trace msg="fetched new page 0 with 64 items (list: 64)" uri="spotify:album:14EWYgtvXZSz0pzvpUCsbL" Oct 26 12:13:47 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:47+02:00" level=debug msg="loading track (paused: false, position: 5367ms)" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=trace msg="emitting websocket event: will_play" Oct 26 12:13:48 volumio-pi volumio[8920]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","play_origin":"album"}} Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="selected format OGG_VORBIS_320 (f3f11e302ac1357c354ad972e5b271a51baa5687)" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="requested aes key for file f3f11e302ac1357c354ad972e5b271a51baa5687, gid: 1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1393" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="fetched first chunk of 66, total size is 34396776 bytes" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=trace msg="seek to 5367ms (diff: 957ms, samples: 236684, bytes: 244632)" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="created new output device" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=info msg="loaded track \"Telegraph Road - Live At Hammersmith Odeon, London / 1983 / Remastered 2023\" (paused: false, position: 5367ms, duration: 776106ms, prefetched: false)" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="fetched chunk 1/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="fetched chunk 2/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=trace msg="scheduling prefetch in 742s" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=trace msg="emitting websocket event: metadata" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=trace msg="emitting websocket event: active" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="sending successful reply for dealer request" Oct 26 12:13:48 volumio-pi volumio[8920]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","name":"Telegraph Road - Live At Hammersmith Odeon, London / 1983 / Remastered 2023","artist_names":["Dire Straits"],"album_name":"Live 1978 - 1992","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029be337912409352852f9b2e7","position":5367,"duration":776106,"release_date":"year:2023 month:11 day:3","track_number":13,"disc_number":1}} Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 26 12:13:48 volumio-pi volumio[8920]: SPOTIFY: received: {"type":"active","data":null} Oct 26 12:13:48 volumio-pi volumio[8920]: info: Aligning Spotify Volume to Volumio Volume Oct 26 12:13:48 volumio-pi volumio[8920]: info: CoreCommandRouter::volumioGetState Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 26 12:13:48 volumio-pi volumio[8920]: info: CorePlayQueue::getTrack 0 Oct 26 12:13:48 volumio-pi volumio[8920]: info: Setting Spotify Volume from Volumio: 100 Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1152" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=debug msg="fetched chunk 3/65, size: 524288" uri="spotify:track:1BnCd4mCmOBGpUzd6RE2bG" Oct 26 12:13:48 volumio-pi go-librespot[9055]: time="2024-10-26T12:13:48+02:00" level=trace msg="emitting websocket event: playing" Oct 26 12:13:48 volumio-pi volumio[8920]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1BnCd4mCmOBGpUzd6RE2bG","play_origin":"album"}} Oct 26 12:13:48 volumio-pi volumio[8920]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 12:13:48 volumio-pi volumio[8920]: TypeError: Cannot read property 'service' of undefined Oct 26 12:13:48 volumio-pi volumio[8920]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Oct 26 12:13:48 volumio-pi volumio[8920]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Oct 26 12:13:48 volumio-pi volumio[8920]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Oct 26 12:13:48 volumio-pi volumio[8920]: at WebSocket.emit (events.js:315:20) Oct 26 12:13:48 volumio-pi volumio[8920]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 26 12:13:48 volumio-pi volumio[8920]: at Receiver.emit (events.js:315:20) Oct 26 12:13:48 volumio-pi volumio[8920]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 26 12:13:48 volumio-pi volumio[8920]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 26 12:13:48 volumio-pi volumio[8920]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 26 12:13:48 volumio-pi volumio[8920]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 26 12:13:48 volumio-pi volumio[8920]: at writeOrBuffer (internal/streams/writable.js:358:12) Oct 26 12:13:48 volumio-pi volumio[8920]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Oct 26 12:13:48 volumio-pi volumio[8920]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 26 12:13:48 volumio-pi volumio[8920]: at Socket.emit (events.js:315:20) Oct 26 12:13:48 volumio-pi volumio[8920]: at addChunk (internal/streams/readable.js:309:12) Oct 26 12:13:48 volumio-pi volumio[8920]: at readableAddChunk (internal/streams/readable.js:284:9) Oct 26 12:13:48 volumio-pi volumio[8920]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 26 12:13:48 volumio-pi sudo[9168]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-26 12:12 Oct 26 12:13:48 volumio-pi sudo[9168]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"