-- Logs begin at Tue 2024-11-26 17:28:52 PST, end at Wed 2024-11-27 16:26:57 PST. -- Nov 27 16:26:29 volumio systemd-timedated[1045]: Changed local time to Wed Nov 27 16:26:29 2024 Nov 27 16:26:29 volumio sudo[1043]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:29 volumio volumio-time-update[625]: volumio-time-update-util: System time updated successfully. Nov 27 16:26:29 volumio volumio[996]: info: Plugin folders cleanup Nov 27 16:26:29 volumio volumio[996]: info: Scanning into folder /volumio/app/plugins/ Nov 27 16:26:29 volumio volumio[996]: info: Scanning category audio_interface Nov 27 16:26:29 volumio volumio[996]: info: Scanning category miscellanea Nov 27 16:26:29 volumio volumio[996]: info: Scanning category music_service Nov 27 16:26:29 volumio volumio[996]: info: Scanning category plugins.json Nov 27 16:26:29 volumio volumio[996]: info: Scanning category system_controller Nov 27 16:26:29 volumio volumio[996]: info: Scanning category user_interface Nov 27 16:26:29 volumio volumio[996]: info: Scanning into folder /data/plugins/ Nov 27 16:26:29 volumio volumio[996]: info: Scanning category music_service Nov 27 16:26:29 volumio volumio[996]: info: Scanning category user_interface Nov 27 16:26:29 volumio volumio[996]: info: Plugin folders cleanup completed Nov 27 16:26:29 volumio volumio[996]: info: ------------------------------------------- Nov 27 16:26:29 volumio volumio[996]: info: ----- Core plugins startup ---- Nov 27 16:26:29 volumio volumio[996]: info: ------------------------------------------- Nov 27 16:26:29 volumio volumio[996]: info: Loading plugins from folder /volumio/app/plugins/ Nov 27 16:26:29 volumio systemd[1]: Starting Daily man-db regeneration... Nov 27 16:26:29 volumio volumio[996]: info: Adding plugin upnp to MyMusic Plugins Nov 27 16:26:29 volumio volumio[996]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 27 16:26:29 volumio systemd[1]: Starting Daily apt download activities... Nov 27 16:26:29 volumio volumio[996]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 27 16:26:29 volumio systemd[1]: Started Volumio Time Update Utility. Nov 27 16:26:29 volumio systemd[1]: Reached target Multi-User System. Nov 27 16:26:29 volumio systemd[1]: Reached target Graphical Interface. Nov 27 16:26:29 volumio volumio[996]: info: Loading plugins from folder /data/plugins/ Nov 27 16:26:29 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 27 16:26:29 volumio volumio[996]: info: Loading plugin "system"... Nov 27 16:26:29 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 27 16:26:29 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 27 16:26:29 volumio volumio[996]: info: Loading plugin "appearance"... Nov 27 16:26:29 volumio systemd[1]: man-db.service: Succeeded. Nov 27 16:26:29 volumio systemd[1]: Started Daily man-db regeneration. Nov 27 16:26:31 volumio systemd[1]: systemd-fsckd.service: Succeeded. Nov 27 16:26:31 volumio volumio[996]: info: Loading plugin "network"... Nov 27 16:26:31 volumio volumio[996]: info: Refreshing Cached IP Addresses Nov 27 16:26:31 volumio sudo[1078]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 27 16:26:31 volumio sudo[1078]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:31 volumio sudo[1078]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:31 volumio sudo[1080]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 27 16:26:31 volumio sudo[1080]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:31 volumio sudo[1080]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:31 volumio volumio[996]: info: Loading plugin "services"... Nov 27 16:26:31 volumio volumio[996]: info: Loading plugin "alsa_controller"... Nov 27 16:26:31 volumio sudo[1089]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Nov 27 16:26:31 volumio sudo[1089]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:31 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 27 16:26:31 volumio volumio[996]: info: Loading plugin "wizard"... Nov 27 16:26:31 volumio volumio[996]: info: Loading plugin "networkfs"... Nov 27 16:26:32 volumio volumio[996]: info: Starting Udev Watcher for removable devices Nov 27 16:26:32 volumio sudo[1110]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Arnold R Panganiban,password=ArP29952995,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.12.251/Music /mnt/NAS/ARP_FLACs Nov 27 16:26:32 volumio sudo[1110]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:32 volumio volumio[996]: info: Ignoring mount for partition: boot Nov 27 16:26:32 volumio volumio[996]: info: Ignoring mount for partition: volumio Nov 27 16:26:32 volumio volumio[996]: info: Ignoring mount for partition: volumio_data Nov 27 16:26:32 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 27 16:26:32 volumio volumio[996]: info: Loading plugin "volumio_command_line_client"... Nov 27 16:26:32 volumio volumio[996]: info: Loading plugin "upnp"... Nov 27 16:26:32 volumio volumio[996]: info: [1732753592139] Starting Upmpd Daemon Nov 27 16:26:32 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 27 16:26:32 volumio volumio[996]: info: Loading plugin "my_music"... Nov 27 16:26:32 volumio volumio[996]: info: Loading plugin "mpd"... Nov 27 16:26:32 volumio sh[511]: timed out Nov 27 16:26:32 volumio dhcpcd[562]: timed out Nov 27 16:26:32 volumio sh[511]: dhcpcd exited Nov 27 16:26:32 volumio dhcpcd[562]: dhcpcd exited Nov 27 16:26:32 volumio sh[511]: ifup: failed to bring up eth0 Nov 27 16:26:32 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Nov 27 16:26:32 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Nov 27 16:26:32 volumio kernel: Key type cifs.spnego registered Nov 27 16:26:32 volumio kernel: Key type cifs.idmap registered Nov 27 16:26:32 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Nov 27 16:26:32 volumio kernel: CIFS: Attempting to mount //192.168.12.251/Music Nov 27 16:26:32 volumio systemd[1]: apt-daily.service: Succeeded. Nov 27 16:26:32 volumio systemd[1]: Started Daily apt download activities. Nov 27 16:26:32 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Nov 27 16:26:32 volumio volumio[996]: info: Loading plugin "upnp_browser"... Nov 27 16:26:33 volumio volumio[996]: info: Loading plugin "alarm-clock"... Nov 27 16:26:33 volumio volumio[996]: info: Loading plugin "airplay_emulation"... Nov 27 16:26:33 volumio volumio[996]: info: Starting Shairport Sync Nov 27 16:26:33 volumio volumio[996]: info: Loading plugin "last_100"... Nov 27 16:26:33 volumio volumio[996]: info: Loading plugin "webradio"... Nov 27 16:26:33 volumio volumio[996]: info: Loading plugin "i2s_dacs"... Nov 27 16:26:33 volumio volumio[996]: info: Loading plugin "volumiodiscovery"... Nov 27 16:26:33 volumio volumio[996]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 27 16:26:33 volumio volumio[996]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 27 16:26:33 volumio node[996]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 27 16:26:33 volumio volumio[996]: *** WARNING *** For more information see Nov 27 16:26:33 volumio volumio[996]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 27 16:26:33 volumio volumio[996]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 27 16:26:33 volumio volumio[996]: *** WARNING *** For more information see Nov 27 16:26:33 volumio node[996]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 27 16:26:33 volumio node[996]: *** WARNING *** For more information see Nov 27 16:26:33 volumio node[996]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 27 16:26:33 volumio node[996]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 27 16:26:33 volumio node[996]: *** WARNING *** For more information see Nov 27 16:26:33 volumio volumio[996]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 27 16:26:34 volumio volumio[996]: info: Discovery: Started advertising with name: Volumio Nov 27 16:26:34 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 27 16:26:34 volumio volumio[996]: info: Loading plugin "spop"... Nov 27 16:26:34 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Nov 27 16:26:35 volumio systemd[1]: Started Daily apt upgrade and clean activities. Nov 27 16:26:35 volumio systemd[1]: Startup finished in 13.590s (kernel) + 39.125s (userspace) = 52.716s. Nov 27 16:26:35 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Nov 27 16:26:35 volumio volumio-remote-updater[621]: [2024-11-27 16:26:35] [connect] Successful connection Nov 27 16:26:35 volumio sudo[1089]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:36 volumio volumio[996]: info: Loading plugin "peppy_screensaver"... Nov 27 16:26:36 volumio volumio[996]: info: Applying required configuration parameters for plugin peppy_screensaver Nov 27 16:26:36 volumio volumio[996]: info: Loading plugin "outputs"... Nov 27 16:26:36 volumio volumio[996]: info: Loading plugin "albumart"... Nov 27 16:26:36 volumio volumio[996]: info: Plugin example_plugin is not enabled Nov 27 16:26:36 volumio volumio[996]: info: Loading plugin "inputs"... Nov 27 16:26:36 volumio volumio[996]: info: Loading plugin "updater_comm"... Nov 27 16:26:36 volumio volumio[996]: info: Plugin mpdemulation is not enabled Nov 27 16:26:36 volumio volumio[996]: info: Loading plugin "rest_api"... Nov 27 16:26:36 volumio volumio[996]: info: Loading plugin "websocket"... Nov 27 16:26:36 volumio volumio[996]: info: Starting Socket.io Server version 2.3.0 Nov 27 16:26:36 volumio volumio[996]: info: Plugin peppymeterbasic is not enabled Nov 27 16:26:36 volumio volumio[996]: info: Loading plugin "touch_display"... Nov 27 16:26:36 volumio volumio[996]: Forking 3 albumart workers Nov 27 16:26:37 volumio volumio[996]: info: Applying required configuration parameters for plugin touch_display Nov 27 16:26:37 volumio volumio[996]: info: Loading i18n strings for locale en Nov 27 16:26:37 volumio volumio[996]: Updating browse sources language Nov 27 16:26:37 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 27 16:26:37 volumio volumio[996]: Starting albumart workers Nov 27 16:26:37 volumio volumio[996]: Starting albumart workers Nov 27 16:26:37 volumio volumio[996]: Starting albumart workers Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::initPlayerControls Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 27 16:26:38 volumio volumio[996]: Express server listening on port 3000 Nov 27 16:26:38 volumio volumio[996]: [Metrics] WebUI: 12s 80.17ms Nov 27 16:26:38 volumio volumio[996]: info: CoreStateMachine::resetVolumioState Nov 27 16:26:38 volumio volumio[996]: info: CoreStateMachine::getcurrentVolume Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::volumioRetrievevolume Nov 27 16:26:38 volumio volumio[996]: info: Volumio Network Manager: Network status updated: 2 Nov 27 16:26:38 volumio volumio-remote-updater[621]: [2024-11-27 16:26:38] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732753595 101 Nov 27 16:26:38 volumio volumio[996]: 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: 1 Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 27 16:26:38 volumio volumio[996]: info: Discovery: Getting this device information Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:38 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 27 16:26:38 volumio volumio[996]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 27 16:26:38 volumio volumio[996]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 27 16:26:38 volumio volumio[996]: info: Reloading queue from file Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:38 volumio volumio[996]: info: VolumeController:: Volume=86 Mute =false Nov 27 16:26:38 volumio volumio[996]: info: CoreStateMachine::pushState Nov 27 16:26:38 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::volumioPushState Nov 27 16:26:38 volumio volumio[996]: info: CoreStateMachine::updateTrackBlock Nov 27 16:26:38 volumio volumio[996]: info: CorePlayQueue::getTrackBlock Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::volumioRetrievevolume Nov 27 16:26:38 volumio volumio[996]: info: Setting Device type: Raspberry PI Nov 27 16:26:38 volumio volumio[996]: info: CoreStateMachine::setRepeat null single undefined Nov 27 16:26:38 volumio volumio[996]: info: CoreStateMachine::pushState Nov 27 16:26:38 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::volumioPushState Nov 27 16:26:38 volumio volumio[996]: info: CoreStateMachine::setRandom null Nov 27 16:26:38 volumio volumio[996]: info: CoreStateMachine::pushState Nov 27 16:26:38 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:38 volumio volumio[996]: info: CoreCommandRouter::volumioPushState Nov 27 16:26:38 volumio volumio[996]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Nov 27 16:26:38 volumio volumio[996]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Nov 27 16:26:38 volumio volumio[996]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Nov 27 16:26:38 volumio volumio[996]: verbose: New Socket.io Connection to 192.168.12.120:3000 from 192.168.12.23 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 4 Nov 27 16:26:39 volumio volumio[996]: info: Discovery: adding 8977d329-cadb-43af-8119-7dfa7f2d8425 Nov 27 16:26:39 volumio volumio[996]: info: Discovery: Found device Volumio Nov 27 16:26:39 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:39 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:39 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:39 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:39 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Nov 27 16:26:39 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Nov 27 16:26:39 volumio volumio[996]: info: VolumeController:: Volume=86 Mute =false Nov 27 16:26:39 volumio volumio[996]: info: CoreStateMachine::pushState Nov 27 16:26:39 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:39 volumio volumio[996]: info: CoreCommandRouter::volumioPushState Nov 27 16:26:42 volumio sudo[1296]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 27 16:26:42 volumio sudo[1296]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:42 volumio sudo[1296]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:42 volumio sudo[1298]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 27 16:26:42 volumio sudo[1298]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:42 volumio sudo[1298]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:42 volumio sudo[1302]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 27 16:26:42 volumio sudo[1302]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:42 volumio kernel: hwmon hwmon1: Voltage normalised Nov 27 16:26:42 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Nov 27 16:26:42 volumio sudo[1302]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:42 volumio volumio[996]: info: Upmpdcli Daemon Started Nov 27 16:26:42 volumio volumio[1304]: Generating RSA private key, 4096 bit long modulus (2 primes) Nov 27 16:26:44 volumio sudo[1110]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:44 volumio volumio[996]: info: Completed loading Core Plugins Nov 27 16:26:44 volumio volumio[996]: info: Preparing to generate the ALSA configuration file Nov 27 16:26:44 volumio volumio[996]: info: The plugin peppy_screensaver has an ALSA contribution file Peppyalsa.postPeppyalsa.5.conf Nov 27 16:26:44 volumio volumio[996]: info: Reading ALSA contributions from plugins. Nov 27 16:26:44 volumio volumio[996]: info: Asound.conf file unchanged, so no further update is needed Nov 27 16:26:44 volumio volumio[996]: info: Output device has changed, restarting MPD Nov 27 16:26:44 volumio sudo[1322]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 27 16:26:44 volumio volumio[996]: info: Output device has changed, restarting Shairport Sync Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:44 volumio sudo[1322]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:44 volumio sudo[1322]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:44 volumio sudo[1324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 27 16:26:44 volumio sudo[1324]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:44 volumio volumio[996]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 27 16:26:44 volumio systemd[1]: Stopping Music Player Daemon... Nov 27 16:26:44 volumio volumio[996]: info: ___________ START PLUGINS ___________ Nov 27 16:26:44 volumio volumio[996]: info: ControllerMpd::onStart: Initializing MPD Nov 27 16:26:44 volumio volumio[996]: info: Creating MPD Configuration file Nov 27 16:26:44 volumio sudo[1331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 27 16:26:44 volumio sudo[1331]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 27 16:26:44 volumio sudo[1331]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:44 volumio volumio[996]: info: [1732753604700] CoreMusicLibrary::Adding element Media Servers Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 27 16:26:44 volumio sudo[1334]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 27 16:26:44 volumio sudo[1334]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:44 volumio volumio[996]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:44 volumio systemd[1]: mpd.service: Succeeded. Nov 27 16:26:44 volumio systemd[1]: Stopped Music Player Daemon. Nov 27 16:26:44 volumio volumio[996]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 27 16:26:44 volumio volumio[996]: info: [1732753604835] CoreMusicLibrary::Adding element Last_100 Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 27 16:26:44 volumio systemd[1]: Starting Music Player Daemon... Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 27 16:26:44 volumio volumio[996]: info: [1732753604845] CoreMusicLibrary::Adding element Webradio Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 27 16:26:44 volumio volumio[996]: info: Initializing BBC Radios Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:44 volumio volumio[996]: info: Creating Spotify config file Nov 27 16:26:44 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:44 volumio sudo[1342]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 27 16:26:45 volumio sudo[1342]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:45 volumio sudo[1342]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:45 volumio volumio[996]: info: Loading i18n strings for locale en Nov 27 16:26:45 volumio volumio[996]: info: /tmp/myfifo created Nov 27 16:26:45 volumio volumio[996]: info: /tmp/myfifosa created Nov 27 16:26:45 volumio sudo[1360]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd-dummy index=7 pcm_substreams=1 fake_buffer=0 Nov 27 16:26:45 volumio sudo[1360]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:45 volumio sudo[1360]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:45 volumio volumio[996]: info: snd-dummy loaded Nov 27 16:26:45 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:45 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:45 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startShairportSync Nov 27 16:26:45 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:45 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:45 volumio volumio[996]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 27 16:26:45 volumio volumio[996]: info: Loading i18n strings for locale en Nov 27 16:26:45 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 27 16:26:45 volumio volumio[996]: info: Volumio Calling Home Nov 27 16:26:45 volumio sudo[1382]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount --bind /tmp/shairport-sync.conf.tmpl /volumio/app/plugins/music_service/airplay_emulation/shairport-sync.conf.tmpl Nov 27 16:26:45 volumio sudo[1382]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:45 volumio volumio[1304]: .............................++++ Nov 27 16:26:45 volumio sudo[1382]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:46 volumio sudo[1388]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop getty@tty1.service Nov 27 16:26:46 volumio sudo[1388]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:46 volumio sudo[1390]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl disable getty@tty1.service Nov 27 16:26:46 volumio sudo[1390]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:46 volumio sudo[1394]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Nov 27 16:26:46 volumio volumio[996]: error: touch_display: Error detecting backlight interface: Error: ENOENT: no such file or directory, scandir '/sys/class/backlight/' Nov 27 16:26:46 volumio sudo[1394]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:46 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:46 volumio volumio[996]: info: MPD Permissions set Nov 27 16:26:46 volumio volumio[996]: info: MPD Permissions set Nov 27 16:26:46 volumio systemd[1]: Reloading. Nov 27 16:26:46 volumio sudo[1388]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:46 volumio volumio[996]: info: Spotify config file written Nov 27 16:26:46 volumio sudo[1397]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 27 16:26:46 volumio volumio[996]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Nov 27 16:26:46 volumio kernel: hwmon hwmon1: Undervoltage detected! Nov 27 16:26:46 volumio sudo[1397]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:46 volumio volumio[996]: info: Volumio called home Nov 27 16:26:46 volumio volumio[996]: info: touch_display: systemctl stop getty@tty1.service succeeded. Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:46 volumio sudo[1416]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount --bind /tmp/mpd.conf.tmpl /volumio/app/plugins/music_service/mpd/mpd.conf.tmpl Nov 27 16:26:46 volumio sudo[1416]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio sudo[1416]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:46 volumio volumio[996]: info: No need to fix Spotify hosts Nov 27 16:26:47 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Nov 27 16:26:47 volumio mpd[1354]: decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 27 16:26:47 volumio mpd[1354]: output: No 'audio_output' defined in config file Nov 27 16:26:47 volumio mpd[1354]: output: Successfully detected a sndio audio device Nov 27 16:26:47 volumio mpd[1354]: zeroconf: No global port, disabling zeroconf Nov 27 16:26:47 volumio volumio[996]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Nov 27 16:26:47 volumio sudo[1429]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/99-vc4.conf Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: mpd , createMPDFile Nov 27 16:26:47 volumio sudo[1429]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:47 volumio volumio[996]: info: Starting Shairport Sync Nov 27 16:26:47 volumio sudo[1429]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:47 volumio volumio[996]: info: Starting Shairport Sync Nov 27 16:26:47 volumio volumio[996]: info: Starting Shairport Sync Nov 27 16:26:47 volumio sudo[1434]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 27 16:26:47 volumio sudo[1434]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:47 volumio volumio[996]: info: Starting Shairport Sync Nov 27 16:26:47 volumio sudo[1439]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 27 16:26:47 volumio sudo[1439]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:47 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:47 volumio sudo[1432]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 27 16:26:47 volumio sudo[1432]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:47 volumio sudo[1432]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:47 volumio sudo[1441]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 27 16:26:47 volumio sudo[1441]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:47 volumio sudo[1436]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 27 16:26:47 volumio sudo[1436]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:47 volumio volumio[996]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/99-vc4.conf set. Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 27 16:26:47 volumio volumio[996]: info: MPD Permissions set Nov 27 16:26:47 volumio volumio[996]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 27 16:26:47 volumio volumio[996]: SPOTIFY: BQD_LxhqneS-9IEp_6rK5K3fyEsKf1OuZwQh5Vb4__6cNK98R7hIV8_XN-7192RRevg2eonpWcgIOX7viiiPZ4LKlttbCy4H02cJN1jhB5_58_QeJT-I3Mnd-YnQfQA79jT3dD2VVN7566bmWMfIq5kdQ764dOb0PRNa__2BTkBd3y57JKMF1cFEvhXq99XQ83ct77V14vu4z-KLZWU6HQPIovOtZ2yVEY4dJ_7TxHDtHMXDZTWUScLT2ndHoXAb83ETosBuf2MduZ4 Nov 27 16:26:47 volumio volumio[996]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 27 16:26:47 volumio volumio[996]: info: New Spotify access token = BQD_LxhqneS-9IEp_6rK5K3fyEsKf1OuZwQh5Vb4__6cNK98R7hIV8_XN-7192RRevg2eonpWcgIOX7viiiPZ4LKlttbCy4H02cJN1jhB5_58_QeJT-I3Mnd-YnQfQA79jT3dD2VVN7566bmWMfIq5kdQ764dOb0PRNa__2BTkBd3y57JKMF1cFEvhXq99XQ83ct77V14vu4z-KLZWU6HQPIovOtZ2yVEY4dJ_7TxHDtHMXDZTWUScLT2ndHoXAb83ETosBuf2MduZ4 Nov 27 16:26:47 volumio volumio[996]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 27 16:26:47 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: mpd , restartMpd Nov 27 16:26:47 volumio sudo[1390]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:47 volumio systemd[1]: Started Music Player Daemon. Nov 27 16:26:47 volumio sudo[1324]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:47 volumio sudo[1334]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:47 volumio sudo[1455]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 27 16:26:47 volumio sudo[1455]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:47 volumio volumio[996]: info: touch_display: systemctl disable getty@tty1.service succeeded. Nov 27 16:26:47 volumio systemd[1]: Reloading. Nov 27 16:26:48 volumio volumio[996]: error: MPD error: The expression evaluated to a falsy value: Nov 27 16:26:48 volumio volumio[996]: assert.ok(self.idling) Nov 27 16:26:48 volumio volumio[996]: error: The expression evaluated to a falsy value: Nov 27 16:26:48 volumio volumio[996]: assert.ok(self.idling) Nov 27 16:26:48 volumio volumio[996]: info: MPD running with PID1354 Nov 27 16:26:48 volumio volumio[996]: ,establishing connection Nov 27 16:26:48 volumio volumio[996]: error: updateQueue error: null Nov 27 16:26:48 volumio volumio[996]: error: updateQueue error: null Nov 27 16:26:48 volumio volumio[996]: SPOTIFY: User informations: {"country":"US","display_name":"Arnold Panganiban","email":"arnoldp@yahoo.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/22nczajawyur5chdbcackb56q"},"followers":{"href":null,"total":6},"href":"https://api.spotify.com/v1/users/22nczajawyur5chdbcackb56q","id":"22nczajawyur5chdbcackb56q","images":[{"height":300,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=10152373054403701&height=300&width=300&ext=1735334573&hash=AbYL59XrsS1bx4jMd3caHPaF","width":300},{"height":64,"url":"https://platform-lookaside.fbsbx.com/platform/profilepic/?asid=10152373054403701&height=50&width=50&ext=1735334573&hash=AbasTIXzmCiK4cbCEr9qtJQb","width":64}],"product":"premium","type":"user","uri":"spotify:user:22nczajawyur5chdbcackb56q"} Nov 27 16:26:48 volumio volumio[996]: info: Spotify Successfully logged in Nov 27 16:26:48 volumio volumio[996]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 27 16:26:48 volumio volumio[996]: info: [1732753608231] CoreMusicLibrary::Adding element Spotify Nov 27 16:26:48 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 27 16:26:48 volumio volumio[996]: Cannot find translation for source Spotify Nov 27 16:26:48 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Nov 27 16:26:49 volumio sudo[1394]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:49 volumio volumio[996]: info: touch_display: systemctl daemon-reload succeeded. Nov 27 16:26:49 volumio sudo[1473]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Nov 27 16:26:49 volumio sudo[1473]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:49 volumio systemd[1]: Started Volumio Kiosk. Nov 27 16:26:49 volumio systemd[1]: Stopping Music Player Daemon... Nov 27 16:26:49 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 27 16:26:49 volumio systemd[1]: Started go-librespot Daemon. Nov 27 16:26:49 volumio sudo[1397]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:49 volumio go-librespot[1477]: Librespot-go daemon starting... Nov 27 16:26:49 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 27 16:26:49 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 27 16:26:49 volumio systemd[1]: mpd.service: Succeeded. Nov 27 16:26:49 volumio systemd[1]: Stopped Music Player Daemon. Nov 27 16:26:49 volumio sudo[1473]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:49 volumio volumio[996]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Nov 27 16:26:49 volumio volumio[996]: info: touch_display: Volumio Kiosk started. Nov 27 16:26:49 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:49 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:49 volumio volumio[996]: info: Completed starting Core Plugins Nov 27 16:26:49 volumio volumio[996]: info: ------------------------------------------- Nov 27 16:26:49 volumio volumio[996]: info: ----- MyVolumio plugins startup ---- Nov 27 16:26:49 volumio volumio[996]: info: ------------------------------------------- Nov 27 16:26:49 volumio volumio[996]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 27 16:26:49 volumio systemd[1]: Starting Music Player Daemon... Nov 27 16:26:49 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 27 16:26:49 volumio sudo[1436]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:49 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:49 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:49 volumio sudo[1434]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:49 volumio sudo[1441]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:49 volumio volumio[996]: info: Shairport-Sync Started Nov 27 16:26:49 volumio volumio[996]: Error adding Membership: Error: addMembership EINVAL Nov 27 16:26:49 volumio volumio[996]: info: Shairport-Sync Started Nov 27 16:26:49 volumio sudo[1439]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:49 volumio volumio[996]: info: Shairport-Sync Started Nov 27 16:26:49 volumio volumio[996]: info: touch_display: X display number found: 0 Nov 27 16:26:49 volumio sudo[1487]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 27 16:26:49 volumio sudo[1487]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 27 16:26:49 volumio sudo[1487]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:49 volumio volumio[996]: info: touch_display: X display number found: 0 Nov 27 16:26:49 volumio startx[1475]: X.Org X Server 1.20.4 Nov 27 16:26:49 volumio startx[1475]: X Protocol Version 11, Revision 0 Nov 27 16:26:49 volumio startx[1475]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian Nov 27 16:26:49 volumio startx[1475]: Current Operating System: Linux volumio 6.6.56-v7l+ #1803 SMP Thu Oct 10 14:10:41 BST 2024 armv7l Nov 27 16:26:49 volumio startx[1475]: Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 bcm2708_fb.fbwidth=640 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:7C:76:17 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 splash plymouth.ignore-serial-consoles dwc_otg.fiq_enable=1 dwc_otg.fiq_fsm_enable=1 dwc_otg.fiq_fsm_mask=0xF dwc_otg.nak_holdoff=1 quiet console=ttyS0,115200 console=tty1 imgpart=UUID=8543fa12-4125-4451-a534-cec5480e0606 imgfile=/volumio_current.sqsh bootpart=UUID=9C48-E5A3 datapart=UUID=f7cca1c6-391b-47a8-9c19-3b1948539def uuidconfig=cmdline.txt pcie_aspm=off pci=pcie_bus_safe rootwait bootdelay=7 logo.nologo vt.global_cursor_default=0 net.ifnames=0 snd-bcm2835.enable_compat_alsa= snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 loglevel=0 nodebug use_kmsg=no Nov 27 16:26:49 volumio startx[1475]: Build Date: 04 April 2023 07:50:56AM Nov 27 16:26:49 volumio startx[1475]: xorg-server 2:1.20.4-1+rpt4+deb10u9 (https://www.debian.org/support) Nov 27 16:26:49 volumio startx[1475]: Current version of pixman: 0.36.0 Nov 27 16:26:49 volumio startx[1475]: Before reporting problems, check http://wiki.x.org Nov 27 16:26:49 volumio startx[1475]: to make sure that you have the latest version. Nov 27 16:26:49 volumio startx[1475]: Markers: (--) probed, (**) from config file, (==) default setting, Nov 27 16:26:49 volumio startx[1475]: (++) from command line, (!!) notice, (II) informational, Nov 27 16:26:49 volumio startx[1475]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Nov 27 16:26:49 volumio startx[1475]: (==) Log file: "/var/log/Xorg.0.log", Time: Wed Nov 27 16:26:49 2024 Nov 27 16:26:49 volumio startx[1475]: (==) Using config directory: "/etc/X11/xorg.conf.d" Nov 27 16:26:49 volumio startx[1475]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Nov 27 16:26:49 volumio volumio[996]: info: touch_display: X display number found: 0 Nov 27 16:26:49 volumio go-librespot[1477]: time="2024-11-27T16:26:49-08:00" level=info msg="generated new device id: bda4b6b0623617b51d84133752372aac4c17fce8" Nov 27 16:26:49 volumio go-librespot[1477]: time="2024-11-27T16:26:49-08:00" level=debug msg="stored credentials found for 22nczajawyur5chdbcackb56q" Nov 27 16:26:49 volumio volumio[996]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Nov 27 16:26:49 volumio volumio[996]: info: touch_display: X display number found: 0 Nov 27 16:26:50 volumio go-librespot[1477]: time="2024-11-27T16:26:50-08:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 27 16:26:50 volumio go-librespot[1477]: time="2024-11-27T16:26:50-08:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 27 16:26:50 volumio go-librespot[1477]: time="2024-11-27T16:26:50-08:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 27 16:26:50 volumio go-librespot[1477]: time="2024-11-27T16:26:50-08:00" level=debug msg="zeroconf server listening on port 46215" Nov 27 16:26:50 volumio go-librespot[1477]: time="2024-11-27T16:26:50-08:00" level=debug msg="obtained new client token: AAD+ODUwuEPBSyXPWmej7TkuMdk5NwxVLS4vEvxNkMxBlLhl9j0RO6G4a8CYyOe55xk0swZVFXY1bqsv6rezn6NnyJ82cxuyRn/51Id3dXUPvOwA9BN9DKdKOGgBEV+7NowUSGvkftv77JL2LbQ7D5QkCEkmYcKTSmxZOPpgssanWGWWSMQQ538Dv1dDtKXWtMLiCOpQX5EwO6JKFWrVaigCIkDO29q9t8CfY0e46nwEFVOvjSsql31m0yE=" Nov 27 16:26:50 volumio go-librespot[1477]: time="2024-11-27T16:26:50-08:00" level=info msg="connected to ap-guc3.spotify.com:4070" Nov 27 16:26:51 volumio go-librespot[1477]: time="2024-11-27T16:26:51-08:00" level=debug msg="completed keyexchange" Nov 27 16:26:51 volumio mpd[1517]: Nov 27 16:26 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 27 16:26:51 volumio systemd[1]: Started Music Player Daemon. Nov 27 16:26:51 volumio sudo[1455]: pam_unix(sudo:session): session closed for user root Nov 27 16:26:51 volumio volumio[996]: error: updateQueue error: null Nov 27 16:26:51 volumio go-librespot[1477]: time="2024-11-27T16:26:51-08:00" level=debug msg="completed challenge" Nov 27 16:26:51 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:51 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:51 volumio go-librespot[1477]: time="2024-11-27T16:26:51-08:00" level=debug msg="authenticated as 22nczajawyur5chdbcackb56q" Nov 27 16:26:51 volumio volumio[996]: info: touch_display: Setting screensaver timeout to 120 seconds. Nov 27 16:26:51 volumio go-librespot[1477]: time="2024-11-27T16:26:51-08:00" level=debug msg="authenticated as 22nczajawyur5chdbcackb56q" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="dealer connection opened" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="initializing zeroconf session, username: 22nczajawyur5chdbcackb56q" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="autoplay enabled: false" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="received connection id: ZDVlNjU4YTItNGJiZi00ZTZlLTg3ZWUtNTU0ZDM0MzFkY2NkK2RlYWxlcit0Y3A6Ly8wYWNiZGE3Ny5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArRUI5RjIwOTgwRjZCQjkwRkY1RUM2NkFGQTExRDVCQThBQzkzNzdGNDBFRUUwRjc4QTI3RUQwNzYzQTA4OTMyRg==" Nov 27 16:26:52 volumio volumio[996]: info: go-librespot daemon successfully initialized Nov 27 16:26:52 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 27 16:26:52 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 27 16:26:52 volumio volumio[996]: info: Discovery: Getting this device information Nov 27 16:26:52 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:52 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:52 volumio volumio[996]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 27 16:26:52 volumio go-librespot[1477]: time="2024-11-27T16:26:52-08:00" level=debug msg="put connect state because NEW_DEVICE" Nov 27 16:26:53 volumio volumio[996]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 27 16:26:53 volumio volumio[996]: Cannot compose Albumart path Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=debug msg="handling transfer player command from 7a5056518ceec3d37db4fd6f4115066770918613" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E37dLcowtJqi6" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E37dLcowtJqi6" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=debug msg="shuffled context with seed 17159805582103673570 (len: 50, keep: 31)" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=debug msg="loading track (paused: true, position: 89007ms)" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2046" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=trace msg="emitting websocket event: will_play" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=debug msg="selected format OGG_VORBIS_320 (0882d105d0365d8c1098da9d650851248e425067)" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:54 volumio go-librespot[1477]: time="2024-11-27T16:26:54-08:00" level=debug msg="requested aes key for file 0882d105d0365d8c1098da9d650851248e425067, gid: 69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:55 volumio volumio[996]: info: Initializing connection to go-librespot Websocket Nov 27 16:26:55 volumio go-librespot[1477]: time="2024-11-27T16:26:55-08:00" level=debug msg="new websocket client" Nov 27 16:26:55 volumio volumio[996]: info: Connection to go-librespot Websocket established Nov 27 16:26:55 volumio go-librespot[1477]: time="2024-11-27T16:26:55-08:00" level=debug msg="fetched first chunk of 18, total size is 8943324 bytes" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:55 volumio go-librespot[1477]: time="2024-11-27T16:26:55-08:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:55 volumio go-librespot[1477]: time="2024-11-27T16:26:55-08:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="fetched chunk 5/17, size: 524288" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=trace msg="seek to 89007ms (diff: 332ms, samples: 3925208, bytes: 2823349)" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="fetched chunk 8/17, size: 524288" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="fetched chunk 6/17, size: 524288" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="created new output device" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=info msg="loaded track \"Over The Rainbow\" (paused: true, position: 89007ms, duration: 282840ms, prefetched: false)" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=trace msg="emitting websocket event: metadata" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=trace msg="emitting websocket event: active" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="sending successful reply for dealer request" Nov 27 16:26:56 volumio volumio[996]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:69XmGDda7Gd8UITZ80n1HD","name":"Over The Rainbow","artist_names":["Ben Webster"],"album_name":"See You At The Fair","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029d4721ec63a741fd566061ee","position":89007,"duration":282840,"release_date":"year:1964","track_number":3,"disc_number":1}} Nov 27 16:26:56 volumio volumio[996]: SPOTIFY: received: {"type":"active","data":null} Nov 27 16:26:56 volumio volumio[996]: info: Aligning Spotify Volume to Volumio Volume Nov 27 16:26:56 volumio volumio[996]: info: CoreCommandRouter::volumioGetState Nov 27 16:26:56 volumio volumio[996]: info: CorePlayQueue::getTrack 0 Nov 27 16:26:56 volumio volumio[996]: info: Setting Spotify Volume from Volumio: 86 Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="fetched chunk 7/17, size: 524288" uri="spotify:track:69XmGDda7Gd8UITZ80n1HD" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2036" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=trace msg="emitting websocket event: paused" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 27 16:26:56 volumio volumio[996]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:69XmGDda7Gd8UITZ80n1HD","play_origin":"playlist"}} Nov 27 16:26:56 volumio volumio[996]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 27 16:26:56 volumio volumio[996]: TypeError: Cannot read property 'service' of undefined Nov 27 16:26:56 volumio volumio[996]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Nov 27 16:26:56 volumio volumio[996]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Nov 27 16:26:56 volumio volumio[996]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Nov 27 16:26:56 volumio volumio[996]: at WebSocket.emit (events.js:315:20) Nov 27 16:26:56 volumio volumio[996]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 27 16:26:56 volumio volumio[996]: at Receiver.emit (events.js:315:20) Nov 27 16:26:56 volumio volumio[996]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 27 16:26:56 volumio volumio[996]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 27 16:26:56 volumio volumio[996]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 27 16:26:56 volumio volumio[996]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 27 16:26:56 volumio volumio[996]: at writeOrBuffer (internal/streams/writable.js:358:12) Nov 27 16:26:56 volumio volumio[996]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Nov 27 16:26:56 volumio volumio[996]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Nov 27 16:26:56 volumio volumio[996]: at Socket.emit (events.js:315:20) Nov 27 16:26:56 volumio volumio[996]: at addChunk (internal/streams/readable.js:309:12) Nov 27 16:26:56 volumio volumio[996]: at readableAddChunk (internal/streams/readable.js:284:9) Nov 27 16:26:56 volumio volumio[996]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1462" Nov 27 16:26:56 volumio go-librespot[1477]: time="2024-11-27T16:26:56-08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 27 16:26:57 volumio sudo[1665]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-27 16:25 Nov 27 16:26:57 volumio sudo[1665]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"