Apr 12 14:52:17 pi5dev sudo[7453]: volumio : TTY=pts/0 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl -f Apr 12 14:52:17 pi5dev sudo[7453]: pam_unix(sudo:session): session opened for user root(uid=0) by volumio(uid=1000) Apr 12 14:52:22 pi5dev sudo[7471]: volumio : TTY=pts/2 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/systemctl restart volumio Apr 12 14:52:22 pi5dev sudo[7471]: pam_unix(sudo:session): session opened for user root(uid=0) by volumio(uid=1000) Apr 12 14:52:22 pi5dev systemd[1]: Started dynamicswap.service - dynamicswap service. Apr 12 14:52:22 pi5dev systemd[1]: Stopping volumio.service - Volumio Backend Module... Apr 12 14:52:22 pi5dev systemd[1]: dynamicswap.service: Deactivated successfully. Apr 12 14:52:22 pi5dev vtcs[7211]: [2025-04-12 14:52:22.826] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Apr 12 14:52:22 pi5dev volumio-remote-updater[996]: [2025-04-12 14:52:22] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Apr 12 14:52:22 pi5dev volumio-remote-updater[996]: [2025-04-12 14:52:22] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Apr 12 14:52:22 pi5dev systemd[1]: volumio.service: Deactivated successfully. Apr 12 14:52:22 pi5dev systemd[1]: Stopped volumio.service - Volumio Backend Module. Apr 12 14:52:22 pi5dev systemd[1]: volumio.service: Consumed 8.796s CPU time. Apr 12 14:52:22 pi5dev systemd[1]: Started volumio.service - Volumio Backend Module. Apr 12 14:52:22 pi5dev sudo[7471]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:23 pi5dev volumio[7484]: info: ------------------------------------------- Apr 12 14:52:23 pi5dev volumio[7484]: info: ----- Volumio3 ---- Apr 12 14:52:23 pi5dev volumio[7484]: info: ------------------------------------------- Apr 12 14:52:23 pi5dev volumio[7484]: info: ----- System startup ---- Apr 12 14:52:23 pi5dev volumio[7484]: info: ------------------------------------------- Apr 12 14:52:23 pi5dev volumio[7484]: info: MYVOLUMIO Environment detected Apr 12 14:52:23 pi5dev volumio[7484]: info: Plugin folders cleanup Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning into folder /volumio/app/plugins/ Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning category audio_interface Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning category miscellanea Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning category music_service Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning category plugins.json Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning category system_controller Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning category user_interface Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning into folder /data/plugins/ Apr 12 14:52:23 pi5dev volumio[7484]: info: Scanning category user_interface Apr 12 14:52:23 pi5dev volumio[7484]: info: Plugin folders cleanup completed Apr 12 14:52:23 pi5dev volumio[7484]: info: ------------------------------------------- Apr 12 14:52:23 pi5dev volumio[7484]: info: ----- Core plugins startup ---- Apr 12 14:52:23 pi5dev volumio[7484]: info: ------------------------------------------- Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugins from folder /volumio/app/plugins/ Apr 12 14:52:23 pi5dev volumio[7484]: info: Adding plugin upnp to MyMusic Plugins Apr 12 14:52:23 pi5dev volumio[7484]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 12 14:52:23 pi5dev volumio[7484]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugins from folder /data/plugins/ Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "system"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "appearance"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "network"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Refreshing Cached IP Addresses Apr 12 14:52:23 pi5dev sudo[7507]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 12 14:52:23 pi5dev sudo[7507]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:23 pi5dev sudo[7509]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 12 14:52:23 pi5dev sudo[7509]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:23 pi5dev sudo[7507]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:23 pi5dev sudo[7509]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "services"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "alsa_controller"... Apr 12 14:52:23 pi5dev sudo[7518]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 12 14:52:23 pi5dev sudo[7518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:23 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "wizard"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "networkfs"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Starting Udev Watcher for removable devices Apr 12 14:52:23 pi5dev volumio[7484]: info: Ignoring mount for partition: boot Apr 12 14:52:23 pi5dev volumio[7484]: info: Ignoring mount for partition: volumio Apr 12 14:52:23 pi5dev volumio[7484]: info: Ignoring mount for partition: volumio_data Apr 12 14:52:23 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "volumio_command_line_client"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "upnp"... Apr 12 14:52:23 pi5dev volumio[7484]: info: [1744465943723] Starting Upmpd Daemon Apr 12 14:52:23 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "my_music"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "mpd"... Apr 12 14:52:23 pi5dev volumio[7484]: info: Loading plugin "upnp_browser"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "alarm-clock"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "airplay_emulation"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Starting Shairport Sync Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "last_100"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "webradio"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "i2s_dacs"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "volumiodiscovery"... Apr 12 14:52:24 pi5dev volumio[7484]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 12 14:52:24 pi5dev volumio[7484]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 12 14:52:24 pi5dev volumio[7484]: *** WARNING *** For more information see Apr 12 14:52:24 pi5dev volumio[7484]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 12 14:52:24 pi5dev volumio[7484]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 12 14:52:24 pi5dev volumio[7484]: *** WARNING *** For more information see Apr 12 14:52:24 pi5dev node[7484]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 12 14:52:24 pi5dev node[7484]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 12 14:52:24 pi5dev node[7484]: *** WARNING *** For more information see Apr 12 14:52:24 pi5dev node[7484]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 12 14:52:24 pi5dev node[7484]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 12 14:52:24 pi5dev node[7484]: *** WARNING *** For more information see Apr 12 14:52:24 pi5dev volumio[7484]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 12 14:52:24 pi5dev volumio[7484]: info: Discovery: Started advertising with name: pi5dev Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "outputs"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "albumart"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Plugin example_plugin is not enabled Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "inputs"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "updater_comm"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Plugin mpdemulation is not enabled Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "rest_api"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "websocket"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Starting Socket.io Server version 1.7.4 Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading plugin "touch_display"... Apr 12 14:52:24 pi5dev volumio[7484]: info: Applying required configuration parameters for plugin touch_display Apr 12 14:52:24 pi5dev volumio[7539]: Forking 3 albumart workers Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading i18n strings for locale en Apr 12 14:52:24 pi5dev volumio[7484]: Updating browse sources language Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::initPlayerControls Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: Express server listening on port 3000 Apr 12 14:52:24 pi5dev volumio[7484]: [Metrics] WebUI: 1s 157.78ms Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::resetVolumioState Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::getcurrentVolume Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioRetrievevolume Apr 12 14:52:24 pi5dev volumio[7484]: info: Cannot read play queue from file Apr 12 14:52:24 pi5dev volumio[7484]: info: Volumio Network Manager: Network status updated: 1 Apr 12 14:52:24 pi5dev volumio[7484]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::updateTrackBlock Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrackBlock Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioRetrievevolume Apr 12 14:52:24 pi5dev volumio[7484]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::setRepeat undefined single undefined Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::setRandom true Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:24 pi5dev volumio[7484]: info: Setting Device type: Raspberry PI Apr 12 14:52:24 pi5dev volumio[7484]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Apr 12 14:52:24 pi5dev volumio[7484]: info: USB Boot Capable - System SBC Revision found in cpuinfo: e04171 Apr 12 14:52:24 pi5dev volumio[7484]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetVisibleSources Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 12 14:52:24 pi5dev volumio[7484]: info: Received Get System Info Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 12 14:52:24 pi5dev volumio[7484]: info: Discovery: Getting this device information Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:24 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:24 pi5dev volumio[7484]: info: Listing playlists Apr 12 14:52:24 pi5dev volumio[7484]: info: Completed loading Core Plugins Apr 12 14:52:24 pi5dev volumio[7484]: info: Preparing to generate the ALSA configuration file Apr 12 14:52:24 pi5dev volumio[7484]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Apr 12 14:52:24 pi5dev volumio[7484]: info: Reading ALSA contributions from plugins. Apr 12 14:52:24 pi5dev volumio[7484]: info: Asound.conf file written Apr 12 14:52:24 pi5dev sudo[7602]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Apr 12 14:52:24 pi5dev sudo[7602]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:24 pi5dev sudo[7602]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:24 pi5dev volumio[7484]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Apr 12 14:52:24 pi5dev volumio[7484]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Apr 12 14:52:24 pi5dev volumio[7484]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Apr 12 14:52:24 pi5dev volumio[7484]: info: Output device has changed, restarting MPD Apr 12 14:52:24 pi5dev sudo[7608]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 12 14:52:24 pi5dev volumio[7484]: info: Output device has changed, restarting Shairport Sync Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:24 pi5dev sudo[7608]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:24 pi5dev sudo[7608]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:24 pi5dev volumio[7484]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 12 14:52:24 pi5dev volumio[7484]: info: ___________ START PLUGINS ___________ Apr 12 14:52:24 pi5dev sudo[7610]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 12 14:52:24 pi5dev volumio[7484]: info: ControllerMpd::onStart: Initializing MPD Apr 12 14:52:24 pi5dev volumio[7484]: info: Creating MPD Configuration file Apr 12 14:52:24 pi5dev sudo[7610]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 14:52:24 pi5dev volumio[7484]: info: [1744465944630] CoreMusicLibrary::Adding element Media Servers Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 14:52:24 pi5dev sudo[7618]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 12 14:52:24 pi5dev sudo[7618]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:24 pi5dev systemd[1]: Stopping mpd.service - Music Player Daemon... Apr 12 14:52:24 pi5dev sudo[7618]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:24 pi5dev sudo[7620]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 12 14:52:24 pi5dev sudo[7620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:24 pi5dev systemd[1]: mpd.service: Deactivated successfully. Apr 12 14:52:24 pi5dev systemd[1]: Stopped mpd.service - Music Player Daemon. Apr 12 14:52:24 pi5dev systemd[1]: mpd.socket: Deactivated successfully. Apr 12 14:52:24 pi5dev systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Apr 12 14:52:24 pi5dev systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Apr 12 14:52:24 pi5dev volumio[7484]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 14:52:24 pi5dev volumio[7484]: info: [1744465944697] CoreMusicLibrary::Adding element Last_100 Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 14:52:24 pi5dev volumio[7484]: info: [1744465944698] CoreMusicLibrary::Adding element Webradio Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 14:52:24 pi5dev volumio[7550]: Starting albumart workers Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 14:52:24 pi5dev volumio[7484]: info: Initializing BBC Radios Apr 12 14:52:24 pi5dev systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Apr 12 14:52:24 pi5dev systemd[1]: Starting mpd.service - Music Player Daemon... Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:24 pi5dev volumio[7484]: info: Loading i18n strings for locale en Apr 12 14:52:24 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 14:52:24 pi5dev volumio[7484]: info: Volumio Calling Home Apr 12 14:52:24 pi5dev volumio[7549]: Starting albumart workers Apr 12 14:52:24 pi5dev sudo[7656]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Apr 12 14:52:24 pi5dev sudo[7656]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:24 pi5dev sudo[7654]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Apr 12 14:52:24 pi5dev sudo[7652]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Apr 12 14:52:24 pi5dev sudo[7652]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:24 pi5dev sudo[7638]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 12 14:52:24 pi5dev sudo[7638]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Apr 12 14:52:24 pi5dev sudo[7654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:24 pi5dev sudo[7638]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:24 pi5dev systemd[1]: Reloading. Apr 12 14:52:24 pi5dev volumio[7558]: Starting albumart workers Apr 12 14:52:25 pi5dev systemd[1]: /lib/systemd/system/volumio-remote-updater.service:5: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Apr 12 14:52:25 pi5dev systemd[1]: /lib/systemd/system/volumio-remote-updater.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: Backlight interface detected. Apr 12 14:52:25 pi5dev volumio[7484]: info: MPD Permissions set Apr 12 14:52:25 pi5dev volumio[7484]: info: MPD Permissions set Apr 12 14:52:25 pi5dev volumio[7484]: info: Volumio called home Apr 12 14:52:25 pi5dev volumio[7484]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:25 pi5dev sudo[7708]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/class/backlight/11-0045/brightness Apr 12 14:52:25 pi5dev sudo[7708]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:25 pi5dev sudo[7708]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: Raspberry Pi Foundation touch screen detected. Apr 12 14:52:25 pi5dev sudo[7711]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Apr 12 14:52:25 pi5dev sudo[7711]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:25 pi5dev sudo[7711]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev volumio[7484]: info: Starting Shairport Sync Apr 12 14:52:25 pi5dev volumio[7484]: info: Starting Shairport Sync Apr 12 14:52:25 pi5dev systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Apr 12 14:52:25 pi5dev systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Apr 12 14:52:25 pi5dev sudo[7713]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf Apr 12 14:52:25 pi5dev sudo[7713]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:25 pi5dev sudo[7713]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev volumio[7484]: info: Starting Shairport Sync Apr 12 14:52:25 pi5dev sudo[7716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 12 14:52:25 pi5dev sudo[7716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:25 pi5dev sudo[7719]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 12 14:52:25 pi5dev sudo[7719]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:25 pi5dev sudo[7723]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: File permissions for backlight brightness control set. Apr 12 14:52:25 pi5dev sudo[7723]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:25 pi5dev sudo[7656]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. Apr 12 14:52:25 pi5dev systemd[1]: Reloading. Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: systemctl daemon-reload succeeded. Apr 12 14:52:25 pi5dev sudo[7730]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Apr 12 14:52:25 pi5dev sudo[7730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:25 pi5dev volumio[7484]: info: Discovery: adding de3fdaf1-89d9-4ed3-bb96-ff6c4f4ef275 Apr 12 14:52:25 pi5dev volumio[7484]: info: Discovery: Found device pi5dev Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:25 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:25 pi5dev volumio[7484]: info: Discovery: this is already registered, de3fdaf1-89d9-4ed3-bb96-ff6c4f4ef275 Apr 12 14:52:25 pi5dev volumio[7484]: info: Discovery: Found device pi5dev Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:25 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:25 pi5dev volumio[7484]: info: Discovery: this is already registered, de3fdaf1-89d9-4ed3-bb96-ff6c4f4ef275 Apr 12 14:52:25 pi5dev volumio[7484]: info: Discovery: Found device pi5dev Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:25 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:25 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:25 pi5dev systemd[1]: /lib/systemd/system/volumio-remote-updater.service:5: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Apr 12 14:52:25 pi5dev systemd[1]: /lib/systemd/system/volumio-remote-updater.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Apr 12 14:52:25 pi5dev mpd[7661]: Apr 12 14:52 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 12 14:52:25 pi5dev systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Apr 12 14:52:25 pi5dev systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Apr 12 14:52:25 pi5dev systemd[1]: Started mpd.service - Music Player Daemon. Apr 12 14:52:25 pi5dev sudo[7654]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev sudo[7610]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev sudo[7620]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: systemctl disable getty@tty1.service succeeded. Apr 12 14:52:25 pi5dev systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Apr 12 14:52:25 pi5dev sudo[7730]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev systemd[1]: shairport-sync.service: Deactivated successfully. Apr 12 14:52:25 pi5dev systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Apr 12 14:52:25 pi5dev systemd[1]: shairport-sync.service: Consumed 1.634s CPU time. Apr 12 14:52:25 pi5dev sudo[7652]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev volumio[7484]: error: MPD error: The expression evaluated to a falsy value: Apr 12 14:52:25 pi5dev volumio[7484]: assert.ok(self.idling) Apr 12 14:52:25 pi5dev volumio[7484]: error: The expression evaluated to a falsy value: Apr 12 14:52:25 pi5dev volumio[7484]: assert.ok(self.idling) Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: systemctl stop getty@tty1.service succeeded. Apr 12 14:52:25 pi5dev volumio[7484]: info: MPD running with PID7661 Apr 12 14:52:25 pi5dev volumio[7484]: ,establishing connection Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: Volumio Kiosk started. Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:25 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:25 pi5dev volumio[7484]: info: Completed starting Core Plugins Apr 12 14:52:25 pi5dev volumio[7484]: info: ------------------------------------------- Apr 12 14:52:25 pi5dev volumio[7484]: info: ----- MyVolumio plugins startup ---- Apr 12 14:52:25 pi5dev volumio[7484]: info: ------------------------------------------- Apr 12 14:52:25 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 12 14:52:25 pi5dev volumio[7484]: error: updateQueue error: null Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:25 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:25 pi5dev volumio[7484]: error: updateQueue error: null Apr 12 14:52:25 pi5dev systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Apr 12 14:52:25 pi5dev sudo[7719]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev sudo[7723]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev sudo[7716]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:25 pi5dev volumio[7484]: info: Shairport-Sync Started Apr 12 14:52:25 pi5dev volumio[7484]: Error adding Membership: Error: addMembership EINVAL Apr 12 14:52:25 pi5dev volumio[7484]: info: Shairport-Sync Started Apr 12 14:52:25 pi5dev volumio[7484]: info: Shairport-Sync Started Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: X display number found: 0 Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: X display number found: 0 Apr 12 14:52:25 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:25 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:25 pi5dev volumio[7484]: info: touch_display: Setting screensaver timeout to 120 seconds. Apr 12 14:52:27 pi5dev sudo[7518]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:27 pi5dev volumio-remote-updater[996]: [2025-04-12 14:52:27] [connect] Successful connection Apr 12 14:52:27 pi5dev volumio-remote-updater[996]: [2025-04-12 14:52:27] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1744465947 101 Apr 12 14:52:27 pi5dev volumio[7484]: 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: 4 Apr 12 14:52:30 pi5dev volumio[7484]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Apr 12 14:52:33 pi5dev sudo[7794]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 12 14:52:33 pi5dev sudo[7794]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:33 pi5dev sudo[7796]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 12 14:52:33 pi5dev sudo[7794]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:33 pi5dev sudo[7796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:33 pi5dev sudo[7796]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:33 pi5dev sudo[7800]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 12 14:52:33 pi5dev sudo[7800]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:33 pi5dev sudo[7800]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:33 pi5dev volumio[7484]: info: Upmpdcli Daemon Started Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Apr 12 14:52:34 pi5dev volumio[7484]: info: Adding plugin bluetooth to MyMusic Plugins Apr 12 14:52:34 pi5dev volumio[7484]: info: Adding plugin multiroom to MyMusic Plugins Apr 12 14:52:34 pi5dev volumio[7484]: info: Adding plugin metavolumio to MyMusic Plugins Apr 12 14:52:34 pi5dev volumio[7484]: info: Adding plugin cd_controller to MyMusic Plugins Apr 12 14:52:34 pi5dev volumio[7484]: info: Adding plugin smart_inputs to MyMusic Plugins Apr 12 14:52:34 pi5dev volumio[7484]: info: Adding plugin tidalconnect to MyMusic Plugins Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Apr 12 14:52:34 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:34 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:34 pi5dev volumio[7484]: info: Starting MyVolumio Remote Streaming Endpoints Apr 12 14:52:34 pi5dev volumio[7484]: info: MyVolumio login type: Token Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Apr 12 14:52:34 pi5dev volumio[7484]: info: Streaming services startup Apr 12 14:52:34 pi5dev volumio[7484]: info: Starting Streaming Daemon Apr 12 14:52:34 pi5dev sudo[7803]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 12 14:52:34 pi5dev sudo[7803]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:34 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Apr 12 14:52:34 pi5dev sudo[7803]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:34 pi5dev volumio[7484]: error: Cannot start Volumio Streaming Daemon Apr 12 14:52:34 pi5dev volumio[7484]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Apr 12 14:52:34 pi5dev volumio[7484]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Apr 12 14:52:34 pi5dev volumio[7484]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Apr 12 14:52:35 pi5dev volumio[7484]: info: MyVolumio token set successfully Apr 12 14:52:35 pi5dev volumio[7484]: info: MYVOLUMIO: Adding device Apr 12 14:52:35 pi5dev volumio[7484]: info: MYVOLUMIO: Evaluating Server Apr 12 14:52:35 pi5dev volumio[7484]: info: MyVolumio Plan changed: premium Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Apr 12 14:52:35 pi5dev volumio[7484]: info: Removing browser output: myVolumio user plan is not superstar Apr 12 14:52:35 pi5dev volumio[7484]: info: Removing audio output: Apr 12 14:52:35 pi5dev volumio[7484]: info: MYVOLUMIO: Adding device Apr 12 14:52:35 pi5dev volumio[7484]: info: MYVOLUMIO: Evaluating Server Apr 12 14:52:35 pi5dev volumio[7484]: info: Remote config written successfully Apr 12 14:52:35 pi5dev volumio[7484]: info: Starting Tunnel 1 Apr 12 14:52:35 pi5dev volumio[7484]: info: Starting Tunnel Connection Checker Apr 12 14:52:35 pi5dev volumio[7484]: info: Completed starting MyVolumio Plugin Apr 12 14:52:35 pi5dev volumio[7484]: info: MYVolumio Device enabled Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Apr 12 14:52:35 pi5dev volumio[7484]: info: MyVolumio status changed Apr 12 14:52:35 pi5dev volumio[7484]: info: Streaming services startup Apr 12 14:52:35 pi5dev volumio[7484]: info: Starting Streaming Daemon Apr 12 14:52:35 pi5dev sudo[7842]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Apr 12 14:52:35 pi5dev sudo[7842]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Apr 12 14:52:35 pi5dev sudo[7842]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:35 pi5dev volumio[7484]: warn: [MyVolumio PluginManager] It looks like we're trying to load a cleartext plugin in: /myvolumio/plugins/audio_interface/bluetooth/index.js Apr 12 14:52:35 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Apr 12 14:52:35 pi5dev volumio[7484]: error: [MyVolumio PluginManager] ATTENTION!!!: Plugin bluetooth does not return adequate promise from onVolumioStart: please update! Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Apr 12 14:52:35 pi5dev sudo[7846]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Apr 12 14:52:35 pi5dev sudo[7846]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:35 pi5dev sudo[7846]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:35 pi5dev volumio[7484]: /usr/bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Apr 12 14:52:35 pi5dev volumio[7484]: info: MRS: MultiRoom plugin initialized Apr 12 14:52:35 pi5dev volumio[7484]: info: MRS: STOPPING SNAPCLIENT Apr 12 14:52:35 pi5dev volumio[7484]: info: MRS: Snap server stop Apr 12 14:52:35 pi5dev volumio[7484]: info: MRS: STOPPING volumioStreaming Apr 12 14:52:35 pi5dev sudo[7863]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Apr 12 14:52:35 pi5dev sudo[7863]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:35 pi5dev sudo[7865]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Apr 12 14:52:35 pi5dev sudo[7865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Apr 12 14:52:35 pi5dev sudo[7867]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Apr 12 14:52:35 pi5dev sudo[7867]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:35 pi5dev sudo[7871]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Apr 12 14:52:35 pi5dev sudo[7871]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:35 pi5dev sudo[7871]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:35 pi5dev sudo[7863]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Apr 12 14:52:35 pi5dev sudo[7867]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:35 pi5dev sudo[7865]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Apr 12 14:52:35 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Apr 12 14:52:35 pi5dev volumio[7484]: info: Preparing to generate the ALSA configuration file Apr 12 14:52:35 pi5dev volumio[7484]: info: Setting Geolocation for MyVolumio to eu3 Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:35 pi5dev volumio[7484]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Apr 12 14:52:35 pi5dev volumio[7484]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Apr 12 14:52:35 pi5dev volumio[7484]: info: Reading ALSA contributions from plugins. Apr 12 14:52:35 pi5dev volumio[7484]: info: Setting Geolocation for MyVolumio to eu3 Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:35 pi5dev volumio[7484]: info: MRS: Removed streaming files Apr 12 14:52:35 pi5dev volumio[7484]: info: MRS: volumioStreaming STOPPED Apr 12 14:52:35 pi5dev volumio[7484]: info: MRS: SNAPSERVER STOPPED Apr 12 14:52:35 pi5dev volumio[7484]: info: MRS: SNAPCLIENT STOPPED Apr 12 14:52:35 pi5dev volumio[7484]: error: Cannot start Volumio Streaming Daemon Apr 12 14:52:35 pi5dev volumio[7484]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Apr 12 14:52:35 pi5dev volumio[7484]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Apr 12 14:52:35 pi5dev volumio[7484]: info: Asound.conf file written Apr 12 14:52:35 pi5dev sudo[7876]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Apr 12 14:52:35 pi5dev sudo[7876]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:35 pi5dev sudo[7876]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:35 pi5dev volumio[7484]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Apr 12 14:52:35 pi5dev volumio[7484]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Apr 12 14:52:35 pi5dev volumio[7484]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Apr 12 14:52:35 pi5dev volumio[7484]: info: Output device has changed, restarting MPD Apr 12 14:52:35 pi5dev sudo[7882]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 12 14:52:35 pi5dev sudo[7882]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:35 pi5dev sudo[7882]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:35 pi5dev volumio[7484]: info: Output device has changed, restarting Shairport Sync Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:35 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:35 pi5dev sudo[7885]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 12 14:52:35 pi5dev sudo[7885]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:36 pi5dev volumio[7484]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 12 14:52:36 pi5dev volumio[7484]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [FUNC] onStart Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Apr 12 14:52:36 pi5dev systemd[1]: Stopping mpd.service - Music Player Daemon... Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Apr 12 14:52:36 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output for this device Apr 12 14:52:36 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding audio output: Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding audio output: Apr 12 14:52:36 pi5dev systemd[1]: mpd.service: Deactivated successfully. Apr 12 14:52:36 pi5dev systemd[1]: Stopped mpd.service - Music Player Daemon. Apr 12 14:52:36 pi5dev volumio[7484]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev systemd[1]: mpd.socket: Deactivated successfully. Apr 12 14:52:36 pi5dev systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Apr 12 14:52:36 pi5dev systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding METAVOLUMIO REST API Endpoints Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Apr 12 14:52:36 pi5dev volumio[7484]: info: Preparing CD Folders Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding CD REST API Endpoints Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Apr 12 14:52:36 pi5dev volumio[7484]: info: Starting UDEV Watcher for CD Apr 12 14:52:36 pi5dev volumio[7484]: info: Detecting CD presence with UDEV Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Apr 12 14:52:36 pi5dev bluetoothd[973]: Path / reserved for Adv Monitor app :1.130 Apr 12 14:52:36 pi5dev bluetoothd[973]: Adv Monitor app :1.130 disconnected from D-Bus Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding inputs REST Endpoints Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Apr 12 14:52:36 pi5dev volumio[7484]: info: Scanning Audio Inputs Apr 12 14:52:36 pi5dev volumio[7484]: info: Checking against Known Cards name Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding Server instance for streaming Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Apr 12 14:52:36 pi5dev volumio[7484]: error: Hi Res Audio Failed Login: Missing Login Data Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding HIGHRESAUDIO REST API Endpoints Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Apr 12 14:52:36 pi5dev volumio[7484]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Apr 12 14:52:36 pi5dev volumio[7484]: info: Stopping AccessToken refresher cron Apr 12 14:52:36 pi5dev sudo[7903]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Apr 12 14:52:36 pi5dev sudo[7903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:36 pi5dev systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Apr 12 14:52:36 pi5dev systemd[1]: Starting mpd.service - Music Player Daemon... Apr 12 14:52:36 pi5dev volumio[7484]: info: AccessToken refresher cron started Apr 12 14:52:36 pi5dev volumio[7484]: info: Stopping AccessToken refresher cron for QOBUZ Apr 12 14:52:36 pi5dev systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Apr 12 14:52:36 pi5dev volumio[7484]: info: AccessToken refresher cron started for QOBUZ Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding TIDAL REST API Endpoints Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding QOBUZ REST API Endpoints Apr 12 14:52:36 pi5dev systemd[1]: vtcs.service: Deactivated successfully. Apr 12 14:52:36 pi5dev systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Apr 12 14:52:36 pi5dev sudo[7903]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Apr 12 14:52:36 pi5dev volumio[7484]: info: MPD Permissions set Apr 12 14:52:36 pi5dev sudo[7908]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Apr 12 14:52:36 pi5dev sudo[7908]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:36 pi5dev sudo[7908]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:36 pi5dev sudo[7905]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 12 14:52:36 pi5dev sudo[7905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Apr 12 14:52:36 pi5dev sudo[7905]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [_watchMediaPlayer] Binding activePlayer for path: /org/bluez/hci0/dev_5C_17_CF_0D_C0_70/player0 Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: activePlayer bound: /org/bluez/hci0/dev_5C_17_CF_0D_C0_70/player0 Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::volumioStop Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreStateMachine::stop Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 12 14:52:36 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 12 14:52:36 pi5dev volumio[7484]: info: Starting Shairport Sync Apr 12 14:52:36 pi5dev volumio[7484]: info: MRS: Found cast device: Chromecast-Ultra-bb5475a65116e0c6bfcdcd498eee7139 Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding audio output: Apr 12 14:52:36 pi5dev sudo[7922]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 12 14:52:36 pi5dev volumio[7484]: info: MRS: Found cast device: Chromecast-5702c0fa26409e4dc282cbccce3735c4 Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding audio output: Apr 12 14:52:36 pi5dev sudo[7922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:36 pi5dev volumio[7484]: info: MRS: Found cast device: Chromecast-Ultra-b8d5e9e179c52d9e75eab34ae52a3903 Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding audio output: Apr 12 14:52:36 pi5dev systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Apr 12 14:52:36 pi5dev volumio[7484]: info: MRS: Found cast device: Google-Nest-Hub-da739cebc7bb692ba8bab67636d07159 Apr 12 14:52:36 pi5dev volumio[7484]: info: Adding audio output: Apr 12 14:52:36 pi5dev systemd[1]: shairport-sync.service: Deactivated successfully. Apr 12 14:52:36 pi5dev systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Apr 12 14:52:36 pi5dev systemd[1]: shairport-sync.service: Consumed 1.527s CPU time. Apr 12 14:52:36 pi5dev systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Apr 12 14:52:36 pi5dev sudo[7922]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:36 pi5dev volumio[7484]: info: Shairport-Sync Started Apr 12 14:52:36 pi5dev volumio[7484]: info: Successfully Added MyVolumio device Apr 12 14:52:36 pi5dev volumio[7484]: info: Successfully Added MyVolumio device Apr 12 14:52:36 pi5dev mpd[7911]: Apr 12 14:52 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 12 14:52:36 pi5dev systemd[1]: Started mpd.service - Music Player Daemon. Apr 12 14:52:36 pi5dev sudo[7885]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:36 pi5dev volumio[7484]: error: updateQueue error: null Apr 12 14:52:36 pi5dev volumio[7484]: info: Updating MyVolumio device info Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: Updating MyVolumio device info Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:36 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:37 pi5dev volumio[7484]: info: Successfully Updated MyVolumio device Apr 12 14:52:37 pi5dev volumio[7484]: info: Successfully Updated MyVolumio device Apr 12 14:52:39 pi5dev volumio[7484]: info: TidalConnect service stoped! Apr 12 14:52:39 pi5dev volumio[7484]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Apr 12 14:52:39 pi5dev volumio[7484]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Apr 12 14:52:39 pi5dev sudo[7950]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Apr 12 14:52:39 pi5dev sudo[7950]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:39 pi5dev systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Apr 12 14:52:39 pi5dev sudo[7950]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:39 pi5dev volumio[7484]: info: Executing endpoint tc_getconfig Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Apr 12 14:52:39 pi5dev vtcs[7953]: STARTING TidalConnect services, version: 1.5.0.45 Apr 12 14:52:39 pi5dev vtcs[7953]: STARTED TidalConnect services. Apr 12 14:52:39 pi5dev volumio[7484]: info: Executing endpoint tc_connect Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Apr 12 14:52:39 pi5dev volumio[7484]: info: Connecting to TidalConnect Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::servicePushState Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:39 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:39 pi5dev volumio[7484]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Apr 12 14:52:39 pi5dev volumio[7484]: verbose: CURRENT POSITION 0 Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::syncState stateService stop Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::syncState currentStatus stop Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:39 pi5dev volumio[7484]: info: No code Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::servicePushState Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:39 pi5dev volumio[7484]: info: CorePlayQueue::getTrack 0 Apr 12 14:52:39 pi5dev volumio[7484]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} Apr 12 14:52:39 pi5dev volumio[7484]: verbose: CURRENT POSITION 0 Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::syncState stateService stop Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::syncState currentStatus stop Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:39 pi5dev volumio[7484]: info: No code Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:39 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:39 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:40 pi5dev sudo[7975]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Apr 12 14:52:40 pi5dev sudo[7975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Apr 12 14:52:40 pi5dev autossh[7237]: received signal to exit (15) Apr 12 14:52:40 pi5dev systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Apr 12 14:52:40 pi5dev systemd[1]: sshtunnel.service: Deactivated successfully. Apr 12 14:52:40 pi5dev systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Apr 12 14:52:40 pi5dev systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Apr 12 14:52:40 pi5dev sudo[7975]: pam_unix(sudo:session): session closed for user root Apr 12 14:52:40 pi5dev autossh[7978]: port set to 0, monitoring disabled Apr 12 14:52:40 pi5dev autossh[7978]: starting ssh (count 1) Apr 12 14:52:40 pi5dev volumio[7484]: info: Remote SSH Started Apr 12 14:52:40 pi5dev autossh[7978]: ssh child pid is 7981 Apr 12 14:52:40 pi5dev volumiossh-tunnel[7981]: Warning: Permanently added '[eu3.myvolumio.org]:2222' (RSA) to the list of known hosts. Apr 12 14:52:40 pi5dev volumio[7484]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Apr 12 14:52:40 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:40 pi5dev volumio[7484]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.dQFd7rFMkUZnTXfKxRPos4Ns44L2.96e25e8b036fdbb047a6171fc7e87d28.state.status' Apr 12 14:52:40 pi5dev bluealsa[1126]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Apr 12 14:52:40 pi5dev bluealsa[1126]: ../src/ba-transport-pcm.c:307: Closing BT socket duplicate [15]: 16 Apr 12 14:52:40 pi5dev bluealsa[1126]: ../src/ba-transport.c:381: Closing A2DP transport: 15 Apr 12 14:52:40 pi5dev bluealsa[1126]: ../src/ba-transport-pcm.c:257: Exiting IO thread [ba-a2dp-sbc]: A2DP Sink (SBC) Apr 12 14:52:40 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [dbus-next] Playback state changed: false from 5C:17:CF:0D:C0:70 Apr 12 14:52:41 pi5dev volumio[7484]: info: MRS: Getting audio outputs on start Apr 12 14:52:41 pi5dev volumio[7484]: info: MRS: Requesting all other devices output Apr 12 14:52:41 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:41 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:42 pi5dev volumio[7484]: info: TidalConnect service started! Apr 12 14:52:42 pi5dev volumio[7484]: [Metrics] CommandRouter: 18s 890.52ms Apr 12 14:52:42 pi5dev volumio[7484]: info: CoreCommandRouter::volumiosetStartupVolume Apr 12 14:52:42 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:42 pi5dev volumio[7484]: info: VolumeController:: Setting startup Volume 65 Apr 12 14:52:42 pi5dev volumio[7484]: info: VolumeController::SetAlsaVolume65 Apr 12 14:52:42 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:42 pi5dev volumio[7484]: info: CoreCommandRouter::Close All Modals sent Apr 12 14:52:42 pi5dev volumio[7484]: info: CoreCommandRouter::Close All Modals sent Apr 12 14:52:42 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:42 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:42 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:42 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:42 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:43 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Apr 12 14:52:43 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Apr 12 14:52:43 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Apr 12 14:52:44 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:44 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:48 pi5dev bluealsa[1126]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Apr 12 14:52:48 pi5dev bluealsa[1126]: ../src/ba-transport.c:319: New A2DP transport: 15 Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [dbus-next] Playback state changed: true from 5C:17:CF:0D:C0:70 Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Playback started, enabling output Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreCommandRouter::volumioStop Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreStateMachine::stop Apr 12 14:52:48 pi5dev bluealsa[1126]: ../src/ba-transport.c:320: A2DP socket MTU: 15: R:672 W:1008 Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreStateMachine::serviceStop Apr 12 14:52:48 pi5dev volumio[7484]: info: Received STOP, but no service to execute it Apr 12 14:52:48 pi5dev bluealsa[1126]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Apr 12 14:52:48 pi5dev bluealsa[1126]: ../src/ba-transport.c:1075: Starting transport: A2DP Sink (SBC) Apr 12 14:52:48 pi5dev bluealsa[1126]: ../src/ba-transport-pcm.c:294: Created BT socket duplicate: [15]: 16 Apr 12 14:52:48 pi5dev bluealsa[1126]: ../src/a2dp-sbc.c:331: PCM IO loop: START: a2dp_sbc_dec_thread: A2DP Sink (SBC) Apr 12 14:52:48 pi5dev bluealsa[1126]: ../src/ba-transport-pcm.c:373: Created new IO thread [ba-a2dp-sbc]: A2DP Sink (SBC) Apr 12 14:52:48 pi5dev dbus-daemon[974]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.129" (uid=1000 pid=7484 comm="/usr/bin/node /volumio/index.js") interface="(unset)" member="(unset)" error name="com.github.dbus_next.Error" requested_reply="0" destination=":1.2" (uid=0 pid=973 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [AAMP] Modular pipeline enabled - using default ALSA route: volumio Apr 12 14:52:48 pi5dev bluetoothd[973]: Adv Monitor app :1.139 disconnected from D-Bus Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Detected connected BT MAC: 5C:17:CF:0D:C0:70 Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Spawning bluealsa-aplay with args: --profile-a2dp --pcm=volumio --pcm-buffer-time=500000 --pcm-period-time=100000 5C:17:CF:0D:C0:70 Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [metaCache] Loaded metadata for 5C:17:CF:0D:C0:70 from file Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Loaded metadata from cache for 5C:17:CF:0D:C0:70 Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8003] D: aplay.c:904: Creating IO worker 5C:17:CF:0D:C0:70 Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8003] D: aplay.c:1320: Starting main loop Apr 12 14:52:48 pi5dev volumio[7484]: bluealsa-aplay: [8004] D: aplay.c:577: Opening BlueALSA source PCM: /org/bluealsa/hci0/dev_5C_17_CF_0D_C0_70/a2dpsnk/source Apr 12 14:52:48 pi5dev bluealsa[1126]: ../src/dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_5C_17_CF_0D_C0_70/a2dpsnk/source Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8004] D: aplay.c:603: Starting IO loop Apr 12 14:52:48 pi5dev bluealsa[1126]: ../src/codec-sbc.c:278: SBC setup: 44100 Hz JointStereo allocation=Loudness blocks=16 sub-bands=8 bit-pool=53 => 327993 bps Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8004] D: aplay.c:732: Opening ALSA playback PCM: name=volumio channels=2 rate=44100 Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Seek received post-resume, pushing metadata Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreCommandRouter::servicePushState Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:48 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:48 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8004] D: aplay.c:339: Opening ALSA mixer: name=default elem=Master index=0 Apr 12 14:52:48 pi5dev volumio[7484]: bluealsa-aplay: [8004] W: aplay.c:350: Couldn't open ALSA mixer: Mixer element not found Apr 12 14:52:48 pi5dev kernel: drm-rp1-dsi 1f00130000.dsi: [drm] rp1dsi: Command time (outvact): 33 Apr 12 14:52:48 pi5dev kernel: drm-rp1-dsi 1f00130000.dsi: [drm] rp1dsi: Nominal Byte clock 90000000 DPI clock 30000000 (parent rate 90000000) Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Received new metadata for 5C:17:CF:0D:C0:70 Apr 12 14:52:48 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [metaCache] Saved metadata to /tmp/bluetooth-cache/meta-5C:17:CF:0D:C0:70.json Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreCommandRouter::servicePushState Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:48 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:48 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:48 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:48 pi5dev volumio[7484]: info: touch_display: Setting screensaver timeout to 0 seconds. Apr 12 14:52:49 pi5dev volumio[7484]: info: BOOT COMPLETED Apr 12 14:52:49 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 12 14:52:49 pi5dev volumio[7484]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Apr 12 14:52:49 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetState Apr 12 14:52:50 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:50 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:50 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:50 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:50 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:50 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:53 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Received new metadata for 5C:17:CF:0D:C0:70 Apr 12 14:52:53 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [metaCache] Saved metadata to /tmp/bluetooth-cache/meta-5C:17:CF:0D:C0:70.json Apr 12 14:52:53 pi5dev volumio[7484]: info: CoreCommandRouter::servicePushState Apr 12 14:52:53 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:53 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:53 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:53 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:53 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::volumioGetBrowseSources Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 12 14:52:54 pi5dev volumio-remote-updater[996]: No test mode Apr 12 14:52:54 pi5dev volumio-remote-updater[996]: Alpha test mode enabled Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Apr 12 14:52:54 pi5dev volumio[7484]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Apr 12 14:52:54 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Apr 12 14:52:55 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPrevious Apr 12 14:52:55 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [FUNC] previous Apr 12 14:52:55 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: sendPrevious -> calling D-Bus Previous() Apr 12 14:52:55 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:55 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:55 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:55 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:55 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:55 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:55 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Received new metadata for 5C:17:CF:0D:C0:70 Apr 12 14:52:55 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [metaCache] Saved metadata to /tmp/bluetooth-cache/meta-5C:17:CF:0D:C0:70.json Apr 12 14:52:55 pi5dev volumio[7484]: info: CoreCommandRouter::servicePushState Apr 12 14:52:55 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:55 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:55 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:55 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:55 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:57 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPause Apr 12 14:52:57 pi5dev volumio[7484]: info: CoreStateMachine::pause Apr 12 14:52:57 pi5dev volumio[7484]: info: CoreStateMachine::stPlaybackTimer Apr 12 14:52:57 pi5dev volumio[7484]: info: CoreStateMachine::servicePause Apr 12 14:52:57 pi5dev volumio[7484]: info: CoreCommandRouter::servicePause Apr 12 14:52:57 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [FUNC] pause Apr 12 14:52:57 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: sendPause -> calling D-Bus Pause() Apr 12 14:52:57 pi5dev volumio[7484]: error: Failed request for metavolumio API Apr 12 14:52:57 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:57 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:57 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:57 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:57 pi5dev volumio[7484]: info: Executing endpoint metavolumio Apr 12 14:52:57 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Apr 12 14:52:59 pi5dev bluealsa[1126]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Apr 12 14:52:59 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [dbus-next] Playback state changed: false from 5C:17:CF:0D:C0:70 Apr 12 14:52:59 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Received pause signal, scheduling idle check Apr 12 14:52:59 pi5dev volumio[7484]: info: CoreCommandRouter::servicePushState Apr 12 14:52:59 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:52:59 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:52:59 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:52:59 pi5dev bluealsa[1126]: ../src/ba-transport-pcm.c:307: Closing BT socket duplicate [15]: 16 Apr 12 14:52:59 pi5dev bluealsa[1126]: ../src/ba-transport.c:381: Closing A2DP transport: 15 Apr 12 14:52:59 pi5dev bluealsa[1126]: ../src/ba-transport-pcm.c:257: Exiting IO thread [ba-a2dp-sbc]: A2DP Sink (SBC) Apr 12 14:52:59 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:52:59 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:52:59 pi5dev volumio[7484]: info: touch_display: Setting screensaver timeout to 120 seconds. Apr 12 14:52:59 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8004] D: aplay.c:643: BT device marked as inactive: 5C:17:CF:0D:C0:70 Apr 12 14:53:00 pi5dev volumio[7484]: info: VolumeController::SetAlsaVolume48 Apr 12 14:53:00 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:53:00 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:53:00 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:53:00 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:53:00 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:53:02 pi5dev volumio[7484]: info: VolumeController::SetAlsaVolume70 Apr 12 14:53:02 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:53:02 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:53:02 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:53:02 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:53:02 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:53:05 pi5dev volumio[7484]: info: CoreCommandRouter::volumioVolatilePlay Apr 12 14:53:05 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [FUNC] play Apr 12 14:53:05 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: sendPlay -> calling D-Bus Play() Apr 12 14:53:06 pi5dev bluealsa[1126]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Apr 12 14:53:06 pi5dev bluealsa[1126]: ../src/ba-transport.c:319: New A2DP transport: 17 Apr 12 14:53:06 pi5dev bluealsa[1126]: ../src/ba-transport.c:320: A2DP socket MTU: 17: R:672 W:1008 Apr 12 14:53:06 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [dbus-next] Playback state changed: true from 5C:17:CF:0D:C0:70 Apr 12 14:53:06 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Playback started, enabling output Apr 12 14:53:06 pi5dev volumio[7484]: info: CoreCommandRouter::volumioStop Apr 12 14:53:06 pi5dev volumio[7484]: info: CoreStateMachine::stop Apr 12 14:53:06 pi5dev bluealsa[1126]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State Apr 12 14:53:06 pi5dev volumio[7484]: info: CoreStateMachine::serviceStop Apr 12 14:53:06 pi5dev volumio[7484]: info: CoreCommandRouter::serviceStop Apr 12 14:53:06 pi5dev bluealsa[1126]: ../src/ba-transport.c:1075: Starting transport: A2DP Sink (SBC) Apr 12 14:53:06 pi5dev volumio[7484]: error: WARNING: No stop method for service [object Object] Apr 12 14:53:06 pi5dev bluealsa[1126]: ../src/ba-transport-pcm.c:294: Created BT socket duplicate: [17]: 15 Apr 12 14:53:06 pi5dev bluealsa[1126]: ../src/a2dp-sbc.c:331: PCM IO loop: START: a2dp_sbc_dec_thread: A2DP Sink (SBC) Apr 12 14:53:06 pi5dev bluealsa[1126]: ../src/ba-transport-pcm.c:373: Created new IO thread [ba-a2dp-sbc]: A2DP Sink (SBC) Apr 12 14:53:06 pi5dev dbus-daemon[974]: [system] Rejected send message, 1 matched rules; type="error", sender=":1.129" (uid=1000 pid=7484 comm="/usr/bin/node /volumio/index.js") interface="(unset)" member="(unset)" error name="com.github.dbus_next.Error" requested_reply="0" destination=":1.2" (uid=0 pid=973 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") Apr 12 14:53:06 pi5dev bluealsa[1126]: ../src/codec-sbc.c:278: SBC setup: 44100 Hz JointStereo allocation=Loudness blocks=16 sub-bands=8 bit-pool=53 => 327993 bps Apr 12 14:53:06 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8004] D: aplay.c:732: Opening ALSA playback PCM: name=volumio channels=2 rate=44100 Apr 12 14:53:06 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8004] D: aplay.c:339: Opening ALSA mixer: name=default elem=Master index=0 Apr 12 14:53:06 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: bluealsa-aplay stderr: bluealsa-aplay: [8004] W: aplay.c:350: Couldn't open ALSA mixer: Mixer element not found Apr 12 14:53:06 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: Seek received post-resume, pushing metadata Apr 12 14:53:06 pi5dev volumio[7484]: info: CoreCommandRouter::servicePushState Apr 12 14:53:06 pi5dev volumio[7484]: info: CoreStateMachine::pushState Apr 12 14:53:06 pi5dev volumio[7484]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 12 14:53:06 pi5dev volumio[7484]: info: CoreCommandRouter::volumioPushState Apr 12 14:53:06 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output update for this device Apr 12 14:53:06 pi5dev volumio[7484]: info: MRS: Pushing multiroomSync output Apr 12 14:53:06 pi5dev volumio[7484]: info: touch_display: Setting screensaver timeout to 0 seconds. Apr 12 14:53:08 pi5dev volumio[7484]: info: VolumeController::SetAlsaVolume42 Apr 12 14:53:08 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [VOLUME HOOK] Intercepted volume 42 - forwarding to Bluetooth device Apr 12 14:53:08 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [VOLUME HOOK] Intercepted volume 42 - forwarding to Bluetooth device Apr 12 14:53:08 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [DEBUG] self.currentMAC = 5C:17:CF:0D:C0:70 Apr 12 14:53:08 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [DEBUG] transportManager.currentMAC = undefined Apr 12 14:53:08 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [DEBUG] MAC resolved for push = 5C:17:CF:0D:C0:70 Apr 12 14:53:08 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: [DEBUG] Capabilities for 5C:17:CF:0D:C0:70: {"Volume":true} Apr 12 14:53:08 pi5dev volumio[7484]: ------------------------------------ BT MESSAGE: pushVolumeToDevice: Device does not support D-Bus volume control (Volume method missing or inactive player) Apr 12 14:53:08 pi5dev volumio[7484]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 14:53:08 pi5dev volumio[7484]: TypeError: self.commandRouter.volumioSetVolume is not a function Apr 12 14:53:08 pi5dev volumio[7484]: at BluetoothInterface.pushVolumeToDevice (/myvolumio/plugins/audio_interface/bluetooth/index.js:117:24) Apr 12 14:53:08 pi5dev volumio[7484]: at self.commandRouter.volumeControl.setVolume (/myvolumio/plugins/audio_interface/bluetooth/index.js:626:16) Apr 12 14:53:08 pi5dev volumio[7484]: at CoreVolumeController.alsavolume (/volumio/app/volumecontrol.js:460:16) Apr 12 14:53:08 pi5dev volumio[7484]: at CoreCommandRouter.volumiosetvolume (/volumio/app/index.js:135:35) Apr 12 14:53:08 pi5dev volumio[7484]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:304:33) Apr 12 14:53:08 pi5dev volumio[7484]: at Socket.emit (node:events:514:28) Apr 12 14:53:08 pi5dev volumio[7484]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Apr 12 14:53:08 pi5dev volumio[7484]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Apr 12 14:53:08 pi5dev volumio[7484]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 14:53:08 pi5dev sudo[8066]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-04-12 14:52' Apr 12 14:53:08 pi5dev sudo[8066]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="8a3b6fcf0dbd7d42207332f6d209906dd2daab56" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Apr 10 17:13:43 UTC 2025" VOLUMIO_VERSION="0.053" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="71bb4de3e1e8e1ea68014647223087d0"