-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Mon 2024-10-28 13:35:22 CET. -- Oct 28 13:35:00 volumio volumio[986]: info: MYVOLUMIO Environment detected Oct 28 13:35:00 volumio volumio[986]: info: Plugin folders cleanup Oct 28 13:35:00 volumio volumio[986]: info: Scanning into folder /volumio/app/plugins/ Oct 28 13:35:00 volumio volumio[986]: info: Scanning category audio_interface Oct 28 13:35:00 volumio volumio[986]: info: Scanning category miscellanea Oct 28 13:35:00 volumio volumio[986]: info: Scanning category music_service Oct 28 13:35:00 volumio volumio[986]: info: Scanning category plugins.json Oct 28 13:35:00 volumio volumio[986]: info: Scanning category system_controller Oct 28 13:35:00 volumio volumio[986]: info: Scanning category user_interface Oct 28 13:35:00 volumio volumio[986]: info: Scanning into folder /data/plugins/ Oct 28 13:35:00 volumio volumio[986]: info: Scanning category music_service Oct 28 13:35:00 volumio volumio[986]: info: Scanning category system_controller Oct 28 13:35:00 volumio volumio[986]: info: Scanning category system_hardware Oct 28 13:35:00 volumio volumio[986]: info: Scanning category user_interface Oct 28 13:35:00 volumio volumio[986]: info: Plugin folders cleanup completed Oct 28 13:35:00 volumio volumio[986]: info: ------------------------------------------- Oct 28 13:35:00 volumio volumio[986]: info: ----- Core plugins startup ---- Oct 28 13:35:00 volumio volumio[986]: info: ------------------------------------------- Oct 28 13:35:00 volumio volumio[986]: info: Loading plugins from folder /volumio/app/plugins/ Oct 28 13:35:00 volumio volumio[986]: info: Adding plugin upnp to MyMusic Plugins Oct 28 13:35:00 volumio volumio[986]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 28 13:35:00 volumio volumio[986]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 28 13:35:00 volumio volumio[986]: info: Loading plugins from folder /data/plugins/ Oct 28 13:35:00 volumio volumio[986]: info: Loading plugin "system"... Oct 28 13:35:00 volumio volumio[986]: info: Loading plugin "appearance"... Oct 28 13:35:01 volumio volumio[986]: info: Loading plugin "network"... Oct 28 13:35:01 volumio volumio[986]: info: Refreshing Cached IP Addresses Oct 28 13:35:01 volumio volumio[986]: info: Loading plugin "services"... Oct 28 13:35:01 volumio sudo[1066]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 28 13:35:01 volumio sudo[1066]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:01 volumio volumio[986]: info: Loading plugin "alsa_controller"... Oct 28 13:35:01 volumio sudo[1066]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:01 volumio sudo[1068]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 28 13:35:01 volumio sudo[1068]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:01 volumio sudo[1068]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:01 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 28 13:35:01 volumio volumio[986]: info: Loading plugin "wizard"... Oct 28 13:35:01 volumio volumio[986]: info: Loading plugin "networkfs"... Oct 28 13:35:01 volumio kernel: hwmon hwmon1: Voltage normalised Oct 28 13:35:02 volumio volumio[986]: info: Starting Udev Watcher for removable devices Oct 28 13:35:02 volumio sudo[1077]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.178.10/Media/Musik /mnt/NAS/Homeserver Oct 28 13:35:02 volumio sudo[1077]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:02 volumio volumio[986]: info: Ignoring mount for partition: boot Oct 28 13:35:02 volumio volumio[986]: info: Ignoring mount for partition: volumio Oct 28 13:35:02 volumio volumio[986]: info: Ignoring mount for partition: volumio_data Oct 28 13:35:02 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 28 13:35:02 volumio volumio[986]: info: Loading plugin "volumio_command_line_client"... Oct 28 13:35:02 volumio volumio[986]: info: Loading plugin "upnp"... Oct 28 13:35:02 volumio volumio[986]: info: [1730118902076] Starting Upmpd Daemon Oct 28 13:35:02 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 28 13:35:02 volumio volumio[986]: info: Loading plugin "my_music"... Oct 28 13:35:02 volumio volumio[986]: info: Loading plugin "mpd"... Oct 28 13:35:02 volumio kernel: Key type cifs.spnego registered Oct 28 13:35:02 volumio kernel: Key type cifs.idmap registered Oct 28 13:35:02 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. Oct 28 13:35:02 volumio kernel: CIFS: Attempting to mount \\192.168.178.10\Media Oct 28 13:35:02 volumio sudo[1077]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:02 volumio volumio[986]: info: Plugin upnp_browser is not enabled Oct 28 13:35:02 volumio volumio[986]: info: Loading plugin "alarm-clock"... Oct 28 13:35:02 volumio volumio[986]: info: Loading plugin "airplay_emulation"... Oct 28 13:35:02 volumio volumio[986]: info: Starting Shairport Sync Oct 28 13:35:02 volumio volumio[986]: info: Loading plugin "last_100"... Oct 28 13:35:02 volumio volumio[986]: info: Loading plugin "webradio"... Oct 28 13:35:03 volumio volumio[986]: info: Loading plugin "i2s_dacs"... Oct 28 13:35:03 volumio volumio[986]: info: Loading plugin "volumiodiscovery"... Oct 28 13:35:03 volumio volumio[986]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 28 13:35:03 volumio volumio[986]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 28 13:35:03 volumio volumio[986]: *** WARNING *** For more information see Oct 28 13:35:03 volumio volumio[986]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 28 13:35:03 volumio node[986]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 28 13:35:03 volumio volumio[986]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 28 13:35:03 volumio volumio[986]: *** WARNING *** For more information see Oct 28 13:35:03 volumio node[986]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 28 13:35:03 volumio node[986]: *** WARNING *** For more information see Oct 28 13:35:03 volumio node[986]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 28 13:35:03 volumio node[986]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 28 13:35:03 volumio node[986]: *** WARNING *** For more information see Oct 28 13:35:03 volumio volumio[986]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 28 13:35:03 volumio volumio[986]: info: Discovery: Started advertising with name: Volumio Oct 28 13:35:03 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 28 13:35:03 volumio volumio[986]: info: Loading plugin "spop"... Oct 28 13:35:04 volumio kernel: hwmon hwmon1: Undervoltage detected! Oct 28 13:35:05 volumio volumio[986]: info: Loading plugin "autostart"... Oct 28 13:35:06 volumio volumio[986]: info: Applying required configuration parameters for plugin autostart Oct 28 13:35:06 volumio volumio[986]: info: AutoStart - onVolumioStart - read config.json Oct 28 13:35:06 volumio volumio[986]: info: Loading plugin "outputs"... Oct 28 13:35:06 volumio volumio[986]: info: Loading plugin "albumart"... Oct 28 13:35:06 volumio volumio[986]: info: Plugin example_plugin is not enabled Oct 28 13:35:06 volumio volumio[986]: info: Loading plugin "inputs"... Oct 28 13:35:06 volumio volumio[986]: info: Loading plugin "updater_comm"... Oct 28 13:35:07 volumio volumio[986]: info: Plugin mpdemulation is not enabled Oct 28 13:35:07 volumio volumio[986]: info: Loading plugin "rest_api"... Oct 28 13:35:07 volumio volumio[986]: info: Loading plugin "websocket"... Oct 28 13:35:07 volumio volumio[986]: info: Starting Socket.io Server version 2.3.0 Oct 28 13:35:07 volumio volumio[986]: info: Loading plugin "gpio_control"... Oct 28 13:35:07 volumio volumio[986]: Forking 3 albumart workers Oct 28 13:35:08 volumio volumio[986]: info: Applying required configuration parameters for plugin gpio_control Oct 28 13:35:08 volumio volumio[986]: info: [GPIO_Control] Detected Raspberry Pi 3 Model B Plus Rev 1.3 Oct 28 13:35:08 volumio volumio[986]: info: [GPIO_Control] 40 GPIOs: true Oct 28 13:35:08 volumio volumio[986]: info: [GPIO_Control] Initialized Oct 28 13:35:08 volumio volumio[986]: info: Loading plugin "touch_display"... Oct 28 13:35:08 volumio volumio[986]: Starting albumart workers Oct 28 13:35:09 volumio volumio[986]: Starting albumart workers Oct 28 13:35:09 volumio volumio[986]: Starting albumart workers Oct 28 13:35:09 volumio volumio[986]: info: Applying required configuration parameters for plugin touch_display Oct 28 13:35:09 volumio volumio[986]: info: Loading i18n strings for locale de Oct 28 13:35:09 volumio volumio[986]: Updating browse sources language Oct 28 13:35:09 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::initPlayerControls Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 28 13:35:10 volumio volumio[986]: Express server listening on port 3000 Oct 28 13:35:10 volumio volumio[986]: [Metrics] WebUI: 12s 649.23ms Oct 28 13:35:10 volumio volumio[986]: info: CoreStateMachine::resetVolumioState Oct 28 13:35:10 volumio volumio[986]: info: CoreStateMachine::getcurrentVolume Oct 28 13:35:10 volumio volumio[986]: info: CoreCommandRouter::volumioRetrievevolume Oct 28 13:35:10 volumio volumio[986]: verbose: New Socket.io Connection to volumio:3000 from 192.168.178.10 UA: okhttp/3.8.1 Engine version: 3 Transport: polling Total Clients: 1 Oct 28 13:35:10 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Oct 28 13:35:10 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 28 13:35:11 volumio volumio[986]: info: Reloading queue from file Oct 28 13:35:11 volumio volumio[986]: info: CoreStateMachine::setRepeat false single undefined Oct 28 13:35:11 volumio volumio[986]: info: CoreStateMachine::pushState Oct 28 13:35:11 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Oct 28 13:35:11 volumio volumio[986]: info: CoreStateMachine::setRandom null Oct 28 13:35:11 volumio volumio[986]: info: CoreStateMachine::pushState Oct 28 13:35:11 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Oct 28 13:35:11 volumio volumio[986]: info: Setting Device type: Raspberry PI Oct 28 13:35:11 volumio volumio[986]: info: Completed loading Core Plugins Oct 28 13:35:11 volumio volumio[986]: info: Preparing to generate the ALSA configuration file Oct 28 13:35:11 volumio volumio[986]: info: VolumeController:: Volume=75 Mute =false Oct 28 13:35:11 volumio volumio[986]: info: CoreStateMachine::pushState Oct 28 13:35:11 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Oct 28 13:35:11 volumio volumio[986]: info: CoreStateMachine::updateTrackBlock Oct 28 13:35:11 volumio volumio[986]: info: CorePlayQueue::getTrackBlock Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::volumioRetrievevolume Oct 28 13:35:11 volumio volumio[986]: info: Discovery: adding 4289f632-7508-49f8-b11e-076ea5c9a843 Oct 28 13:35:11 volumio volumio[986]: info: Discovery: Found device Volumio Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Oct 28 13:35:11 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:11 volumio volumio[986]: info: VolumeController:: Volume=75 Mute =false Oct 28 13:35:11 volumio volumio[986]: info: CoreStateMachine::pushState Oct 28 13:35:11 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Oct 28 13:35:11 volumio volumio[986]: info: Asound.conf file written Oct 28 13:35:11 volumio sudo[1173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Oct 28 13:35:11 volumio sudo[1173]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:11 volumio sudo[1173]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:11 volumio systemd[1]: systemd-fsckd.service: Succeeded. Oct 28 13:35:11 volumio volumio[986]: info: Output device has changed, restarting MPD Oct 28 13:35:11 volumio volumio[986]: info: Output device has changed, restarting Shairport Sync Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:11 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 28 13:35:11 volumio sudo[1178]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 28 13:35:11 volumio sudo[1178]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:11 volumio sudo[1178]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:11 volumio sudo[1180]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 28 13:35:11 volumio sudo[1180]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:12 volumio volumio[986]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 28 13:35:12 volumio volumio[986]: info: ___________ START PLUGINS ___________ Oct 28 13:35:12 volumio volumio[986]: info: ControllerMpd::onStart: Initializing MPD Oct 28 13:35:12 volumio volumio[986]: info: Creating MPD Configuration file Oct 28 13:35:12 volumio systemd[1]: Listening on mpd.socket. Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 28 13:35:12 volumio systemd[1]: Starting Music Player Daemon... Oct 28 13:35:12 volumio sudo[1188]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 28 13:35:12 volumio sudo[1188]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:12 volumio sudo[1188]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:12 volumio sudo[1192]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 28 13:35:12 volumio sudo[1192]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:12 volumio volumio[986]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 28 13:35:12 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 28 13:35:12 volumio systemd[1]: mpd.service: Succeeded. Oct 28 13:35:12 volumio systemd[1]: Stopped Music Player Daemon. Oct 28 13:35:12 volumio systemd[1]: Starting Music Player Daemon... Oct 28 13:35:12 volumio volumio[986]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 28 13:35:12 volumio volumio[986]: info: [1730118912314] CoreMusicLibrary::Adding element Last_100 Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 28 13:35:12 volumio volumio[986]: info: [1730118912323] CoreMusicLibrary::Adding element Webradio Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 28 13:35:12 volumio volumio[986]: info: Initializing BBC Radios Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 28 13:35:12 volumio volumio[986]: info: Creating Spotify config file Oct 28 13:35:12 volumio sudo[1198]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:12 volumio sudo[1198]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:12 volumio volumio[986]: info: AutoStart - onStart Oct 28 13:35:12 volumio sudo[1198]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 28 13:35:12 volumio sudo[1198]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:12 volumio volumio[986]: info: [GPIO_Control] Reading config and creating GPIOs Oct 28 13:35:12 volumio volumio[986]: info: [GPIO_Control] Will set GPIO 24 On when musicPlay Oct 28 13:35:12 volumio volumio[986]: info: [GPIO_Control] Will set GPIO 24 Off when musicPause Oct 28 13:35:12 volumio volumio[986]: info: [GPIO_Control] Will set GPIO 24 Off when musicStop Oct 28 13:35:12 volumio volumio[986]: info: Loading i18n strings for locale de Oct 28 13:35:12 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 28 13:35:12 volumio volumio[986]: info: Volumio Calling Home Oct 28 13:35:12 volumio volumio[986]: info: [GPIO_Control] GPIOs created Oct 28 13:35:12 volumio sudo[1228]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Oct 28 13:35:12 volumio sudo[1228]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:12 volumio systemd[1]: Reloading. Oct 28 13:35:13 volumio sudo[1244]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 28 13:35:13 volumio sudo[1246]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 28 13:35:13 volumio sudo[1244]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:13 volumio sudo[1246]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:13 volumio sudo[1246]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:13 volumio sudo[1244]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:13 volumio volumio[986]: info: MPD Permissions set Oct 28 13:35:13 volumio volumio[986]: info: MPD Permissions set Oct 28 13:35:13 volumio volumio[986]: info: Spotify config file written Oct 28 13:35:13 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 28 13:35:13 volumio sudo[1250]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 28 13:35:13 volumio sudo[1250]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 28 13:35:13 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 28 13:35:13 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. Oct 28 13:35:13 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Oct 28 13:35:13 volumio volumio[986]: info: Volumio called home Oct 28 13:35:14 volumio volumio[986]: info: touch_display: Raspberry Pi Foundation touch screen detected. Oct 28 13:35:14 volumio volumio[986]: info: touch_display: Backlight module of a Raspberry Pi Foundation touch screen detected. Oct 28 13:35:14 volumio volumio[986]: info: Starting Shairport Sync Oct 28 13:35:14 volumio volumio[986]: info: Starting Shairport Sync Oct 28 13:35:14 volumio volumio[986]: info: Starting Shairport Sync Oct 28 13:35:14 volumio sudo[1263]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 28 13:35:14 volumio sudo[1261]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 28 13:35:14 volumio sudo[1263]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:14 volumio sudo[1261]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:14 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Oct 28 13:35:14 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:14 volumio sudo[1267]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 28 13:35:14 volumio sudo[1267]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:14 volumio sudo[1269]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 28 13:35:14 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Oct 28 13:35:14 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:14 volumio volumio-remote-updater[607]: [2024-10-28 13:35:14] [connect] Successful connection Oct 28 13:35:14 volumio sudo[1269]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:14 volumio volumio-remote-updater[607]: [2024-10-28 13:35:14] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1730118914 101 Oct 28 13:35:14 volumio volumio[986]: 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: 5 Oct 28 13:35:14 volumio sudo[1274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod a+w /sys/devices/platform/rpi_backlight/backlight/rpi_backlight/brightness Oct 28 13:35:14 volumio sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:14 volumio sudo[1274]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:14 volumio volumio[986]: info: touch_display: File permissions for backlight brightness control set. Oct 28 13:35:14 volumio sudo[1228]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:14 volumio volumio[986]: info: touch_display: systemctl daemon-reload succeeded. Oct 28 13:35:14 volumio sudo[1278]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Oct 28 13:35:14 volumio sudo[1278]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 28 13:35:14 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 28 13:35:15 volumio systemd[1]: Started Volumio Kiosk. Oct 28 13:35:15 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Oct 28 13:35:15 volumio sudo[1269]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:15 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 28 13:35:15 volumio volumio[986]: info: Upmpdcli Daemon Started Oct 28 13:35:15 volumio systemd[1]: Started go-librespot Daemon. Oct 28 13:35:15 volumio sudo[1250]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:15 volumio go-librespot[1284]: Librespot-go daemon starting... Oct 28 13:35:15 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 28 13:35:15 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 28 13:35:15 volumio sudo[1278]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:15 volumio volumio[986]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Oct 28 13:35:15 volumio volumio[986]: info: touch_display: Volumio Kiosk started Oct 28 13:35:15 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Oct 28 13:35:15 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:15 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Oct 28 13:35:15 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:15 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 28 13:35:15 volumio sudo[1263]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:15 volumio sudo[1261]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:15 volumio sudo[1267]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:15 volumio volumio[986]: info: Shairport-Sync Started Oct 28 13:35:15 volumio volumio[986]: Error adding Membership: Error: addMembership EINVAL Oct 28 13:35:15 volumio volumio[986]: info: Shairport-Sync Started Oct 28 13:35:15 volumio volumio[986]: info: Shairport-Sync Started Oct 28 13:35:15 volumio volumio[986]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Oct 28 13:35:15 volumio volumio[986]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Oct 28 13:35:15 volumio volumio[986]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Oct 28 13:35:15 volumio volumio[986]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Oct 28 13:35:15 volumio startx[1280]: X.Org X Server 1.20.4 Oct 28 13:35:15 volumio startx[1280]: X Protocol Version 11, Revision 0 Oct 28 13:35:15 volumio startx[1280]: Build Operating System: Linux 5.4.0-109-generic armv8l Raspbian Oct 28 13:35:15 volumio startx[1280]: Current Operating System: Linux volumio 6.1.69-v7+ #1710 SMP Thu Dec 21 13:14:13 GMT 2023 armv7l Oct 28 13:35:15 volumio startx[1280]: 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=800 bcm2708_fb.fbheight=480 bcm2708_fb.fbswap=1 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=af3faec2-9654-4fec-8791-d5638a5837ad imgfile=/volumio_current.sqsh bootpart=UUID=2E0A-AE55 datapart=UUID=e98ec3b6-4b81-450d-8409-5291ba448e84 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 Oct 28 13:35:15 volumio startx[1280]: Build Date: 04 April 2023 07:50:56AM Oct 28 13:35:15 volumio startx[1280]: xorg-server 2:1.20.4-1+rpt4+deb10u9 (https://www.debian.org/support) Oct 28 13:35:15 volumio startx[1280]: Current version of pixman: 0.36.0 Oct 28 13:35:15 volumio startx[1280]: Before reporting problems, check http://wiki.x.org Oct 28 13:35:15 volumio startx[1280]: to make sure that you have the latest version. Oct 28 13:35:15 volumio startx[1280]: Markers: (--) probed, (**) from config file, (==) default setting, Oct 28 13:35:15 volumio startx[1280]: (++) from command line, (!!) notice, (II) informational, Oct 28 13:35:15 volumio startx[1280]: (WW) warning, (EE) error, (NI) not implemented, (??) unknown. Oct 28 13:35:15 volumio startx[1280]: (==) Log file: "/var/log/Xorg.0.log", Time: Mon Oct 28 13:35:15 2024 Oct 28 13:35:15 volumio startx[1280]: (==) Using config directory: "/etc/X11/xorg.conf.d" Oct 28 13:35:15 volumio startx[1280]: (==) Using system config directory "/usr/share/X11/xorg.conf.d" Oct 28 13:35:15 volumio volumio[986]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Oct 28 13:35:16 volumio go-librespot[1284]: time="2024-10-28T13:35:16+01:00" level=info msg="generated new device id: 2d647954fb7bcc91398e0e8d4f2766cb288e3505" Oct 28 13:35:16 volumio go-librespot[1284]: time="2024-10-28T13:35:16+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 28 13:35:16 volumio go-librespot[1284]: time="2024-10-28T13:35:16+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 28 13:35:16 volumio go-librespot[1284]: time="2024-10-28T13:35:16+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 28 13:35:16 volumio go-librespot[1284]: time="2024-10-28T13:35:16+01:00" level=debug msg="zeroconf server listening on port 45165" Oct 28 13:35:18 volumio volumio[986]: info: go-librespot daemon successfully initialized Oct 28 13:35:18 volumio mpd[1212]: Oct 28 13:35 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 28 13:35:18 volumio systemd[1]: Started Music Player Daemon. Oct 28 13:35:18 volumio sudo[1192]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:18 volumio sudo[1180]: pam_unix(sudo:session): session closed for user root Oct 28 13:35:18 volumio volumio[986]: Upnp client error: Error: This socket has been ended by the other party Oct 28 13:35:18 volumio volumio[986]: info: Completed starting Core Plugins Oct 28 13:35:18 volumio volumio[986]: info: ------------------------------------------- Oct 28 13:35:18 volumio volumio[986]: info: ----- MyVolumio plugins startup ---- Oct 28 13:35:18 volumio volumio[986]: info: ------------------------------------------- Oct 28 13:35:18 volumio volumio[986]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 28 13:35:18 volumio volumio[986]: error: MPD error: The expression evaluated to a falsy value: Oct 28 13:35:18 volumio volumio[986]: assert.ok(self.idling) Oct 28 13:35:18 volumio volumio[986]: error: The expression evaluated to a falsy value: Oct 28 13:35:18 volumio volumio[986]: assert.ok(self.idling) Oct 28 13:35:18 volumio volumio[986]: info: MPD running with PID1212 Oct 28 13:35:18 volumio volumio[986]: ,establishing connection Oct 28 13:35:18 volumio volumio[986]: error: MPD error: The expression evaluated to a falsy value: Oct 28 13:35:18 volumio volumio[986]: assert.ok(self.idling) Oct 28 13:35:18 volumio volumio[986]: error: The expression evaluated to a falsy value: Oct 28 13:35:18 volumio volumio[986]: assert.ok(self.idling) Oct 28 13:35:18 volumio volumio[986]: error: updateQueue error: null Oct 28 13:35:18 volumio volumio[986]: info: touch_display: Setting screensaver timeout to 120 seconds. Oct 28 13:35:18 volumio go-librespot[1284]: time="2024-10-28T13:35:18+01:00" level=debug msg="obtained new client token: AACEmbPsHT714GF5/tSKDDb3fEPZQ0pSowLfodS26OjIe9ToBOzVCbRpiDXz/9owkOqFPuTL3lF4dKdPKv5VTl+3whoJgybRJ/Qw22vgiqKhCR4s+kGtuTco3XmqF+rCxxD9sN0GHOzpevtUguD0TYZz1acHEwx7E6MBMtBDwZXEkmHe4qlbnwrY0hHmKr35C/IjglRcH/Xu710uTwgUC21nQ7Kv+o3MgMiSHqrNZ69/fd3lXvMmTbJ5M66SMLY=" Oct 28 13:35:18 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Oct 28 13:35:19 volumio go-librespot[1284]: time="2024-10-28T13:35:19+01:00" level=debug msg="completed keyexchange" Oct 28 13:35:19 volumio volumio[1281]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 28 13:35:19 volumio go-librespot[1284]: time="2024-10-28T13:35:19+01:00" level=debug msg="completed challenge" Oct 28 13:35:19 volumio go-librespot[1284]: time="2024-10-28T13:35:19+01:00" level=debug msg="authenticated as mwza48ydla73ia7d1y7ubakqm" Oct 28 13:35:19 volumio go-librespot[1284]: time="2024-10-28T13:35:19+01:00" level=debug msg="authenticated as mwza48ydla73ia7d1y7ubakqm" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="dealer connection opened" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=info msg="accepted zeroconf user mwza48ydla73ia7d1y7ubakqm from Galaxy A51" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="received connection id: OGMzYmRhNjUtNzVlOS00MjczLWEwMzQtYmNhZmM3YWNmZDRlK2RlYWxlcit0Y3A6Ly8wYWNhNTkxZi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQjBCMjRDMjUxMkMxMjY1RUM4MTc5OEQ1NEEwRjZENDlBQUIwRDM5OTFCMEU5QzRENjI1NDMxQUU2RDNFMTNFMA==" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="put connect state because NEW_DEVICE" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="handling transfer player command from 94621ce8fa91818b1b0c06409609b82c754d6fe9" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=trace msg="fetched new page 0 with 26 items (list: 26)" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="loading track spotify:track:5Sj15BrgtOLVrCVela7b6s (paused: false, position: 9690ms)" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=trace msg="emitting websocket event: will_play" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5Sj15BrgtOLVrCVela7b6s" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="requested aes key for file a8d4e91221b75e2f0c3ba259ce8c2d19a1074447, gid: 5Sj15BrgtOLVrCVela7b6s" Oct 28 13:35:20 volumio go-librespot[1284]: time="2024-10-28T13:35:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1382" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1145" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="fetched first chunk of 51, total size is 26404464 bytes" Oct 28 13:35:21 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=trace msg="seek to 9690ms (diff: 156ms, samples: 427329, bytes: 424077)" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="new websocket client" Oct 28 13:35:21 volumio volumio[986]: info: Connection to go-librespot Websocket established Oct 28 13:35:21 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="fetched chunk 3/50, size: 524288" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=info msg="loaded track \"Die Geisterbahn von Herrn Bölcsföldy\" (uri: spotify:track:5Sj15BrgtOLVrCVela7b6s, paused: false, position: 9690ms, duration: 568906ms)" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=trace msg="emitting websocket event: metadata" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=trace msg="emitting websocket event: active" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="sending successful reply for delaer request" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 28 13:35:21 volumio volumio[986]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5Sj15BrgtOLVrCVela7b6s","name":"Die Geisterbahn von Herrn Bölcsföldy","artist_names":["Horst Schwarz","Elmar Tannert"],"album_name":"Spannende Grusel Geschichten","album_cover_url":"https://i.scdn.co/image/ab67616d00001e020ebaaf63195aac3a717a6c22","position":9690,"duration":568906,"release_date":"year:2022 month:2 day:25","track_number":1,"disc_number":1}} Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 28 13:35:21 volumio volumio[986]: SPOTIFY: received: {"type":"active","data":null} Oct 28 13:35:21 volumio volumio[986]: info: Aligning Spotify Volume to Volumio Volume Oct 28 13:35:21 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Oct 28 13:35:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Oct 28 13:35:21 volumio volumio[986]: info: Setting Spotify Volume from Volumio: 75 Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=trace msg="emitting websocket event: playing" Oct 28 13:35:21 volumio volumio[986]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5Sj15BrgtOLVrCVela7b6s","play_origin":"playlist"}} Oct 28 13:35:21 volumio volumio[986]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 28 13:35:21 volumio volumio[986]: TypeError: Cannot read property 'service' of undefined Oct 28 13:35:21 volumio volumio[986]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Oct 28 13:35:21 volumio volumio[986]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Oct 28 13:35:21 volumio volumio[986]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Oct 28 13:35:21 volumio volumio[986]: at WebSocket.emit (events.js:315:20) Oct 28 13:35:21 volumio volumio[986]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Oct 28 13:35:21 volumio volumio[986]: at Receiver.emit (events.js:315:20) Oct 28 13:35:21 volumio volumio[986]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Oct 28 13:35:21 volumio volumio[986]: at internal/process/task_queues.js:149:7 Oct 28 13:35:21 volumio volumio[986]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Oct 28 13:35:21 volumio volumio[986]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Oct 28 13:35:21 volumio volumio[986]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="fetched chunk 1/50, size: 524288" Oct 28 13:35:21 volumio go-librespot[1284]: time="2024-10-28T13:35:21+01:00" level=debug msg="fetched chunk 2/50, size: 524288" Oct 28 13:35:22 volumio go-librespot[1284]: time="2024-10-28T13:35:22+01:00" level=debug msg="fetched chunk 4/50, size: 524288" Oct 28 13:35:22 volumio sudo[1437]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-28 13:34 Oct 28 13:35:22 volumio sudo[1437]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"