-- Logs begin at Sat 2024-10-05 19:02:55 CEST, end at Tue 2024-10-08 11:00:14 CEST. -- Oct 08 10:59:57 volumio ntpd[1017]: receive: Unexpected origin timestamp 0xeaabefdb.5a4b54d1 does not match aorg 0000000000.00000000 from server@89.58.6.143 xmt 0xeaaf730d.f6296f89 Oct 08 10:59:58 volumio ntpd[1017]: receive: Unexpected origin timestamp 0xeaabefdb.5a4f0981 does not match aorg 0000000000.00000000 from server@194.164.164.175 xmt 0xeaaf730d.fab726cc Oct 08 10:59:58 volumio systemd[1]: Starting Daily apt download activities... Oct 08 10:59:58 volumio ntpd[1017]: ntpd exiting on signal 15 (Terminated) Oct 08 10:59:58 volumio ntpd[1017]: 192.168.178.1 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 217.144.138.234 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 168.119.211.223 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 194.164.164.175 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 162.159.200.123 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 89.58.6.143 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 116.203.98.67 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 185.232.69.65 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 193.158.22.13 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio systemd[1]: Stopping Network Time Service... Oct 08 10:59:58 volumio ntpd[1017]: 178.215.228.24 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 148.251.5.46 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 176.9.157.155 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio ntpd[1017]: 185.11.138.90 local addr 192.168.178.51 -> Oct 08 10:59:58 volumio systemd[1]: ntp.service: Succeeded. Oct 08 10:59:58 volumio systemd[1]: Stopped Network Time Service. Oct 08 10:59:58 volumio systemd[1]: Starting Network Time Service... Oct 08 10:59:58 volumio ntpd[1185]: ntpd 4.2.8p12@1.3728-o (1): Starting Oct 08 10:59:58 volumio ntpd[1185]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -c /run/ntp.conf.dhcp -u 103:103 Oct 08 10:59:58 volumio systemd[1]: Started Network Time Service. Oct 08 10:59:58 volumio ntpd[1191]: proto: precision = 0.981 usec (-20) Oct 08 10:59:58 volumio ntpd[1191]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Oct 08 10:59:58 volumio ntpd[1191]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Oct 08 10:59:58 volumio ntpd[1191]: Listen and drop on 0 v6wildcard [::]:123 Oct 08 10:59:58 volumio ntpd[1191]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Oct 08 10:59:58 volumio ntpd[1191]: Listen normally on 2 lo 127.0.0.1:123 Oct 08 10:59:58 volumio ntpd[1191]: Listen normally on 3 eth0 192.168.178.51:123 Oct 08 10:59:58 volumio ntpd[1191]: Listen normally on 4 wlan0 169.254.27.195:123 Oct 08 10:59:58 volumio ntpd[1191]: Listen normally on 5 wlan0 192.168.178.58:123 Oct 08 10:59:58 volumio ntpd[1191]: Listening on routing socket on fd #22 for interface updates Oct 08 10:59:58 volumio ntpd[1191]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Oct 08 10:59:58 volumio ntpd[1191]: kernel reports TIME_ERROR: 0x4041: Clock Unsynchronized Oct 08 10:59:58 volumio wireless.js[633]: trying... Oct 08 10:59:58 volumio sudo[1194]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Oct 08 10:59:58 volumio sudo[1194]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 10:59:58 volumio sudo[1194]: pam_unix(sudo:session): session closed for user root Oct 08 10:59:58 volumio wireless.js[633]: Connected to: ----FRITZ!Box 6690 Oct 08 10:59:58 volumio wireless.js[633]: ---- Oct 08 10:59:58 volumio avahi-daemon[607]: Withdrawing address record for 169.254.27.195 on wlan0. Oct 08 10:59:58 volumio avahi-daemon[607]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 169.254.27.195. Oct 08 10:59:58 volumio dhcpcd[1110]: wlan0: deleting route to 169.254.0.0/16 Oct 08 10:59:58 volumio avahi-daemon[607]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.58. Oct 08 10:59:58 volumio sudo[1199]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 08 10:59:58 volumio sudo[1199]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 10:59:58 volumio sudo[1199]: pam_unix(sudo:session): session closed for user root Oct 08 10:59:58 volumio wireless.js[633]: ... joined AP, wlan0 IPv4 is 192.168.178.58, ipV6 is undefined Oct 08 10:59:58 volumio wireless.js[633]: It's done! AP Oct 08 10:59:58 volumio systemd[1]: Started Wireless Services. Oct 08 10:59:58 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Oct 08 10:59:58 volumio systemd[1]: Started Volumio Backend Module. Oct 08 10:59:58 volumio systemd[1]: Started Volumio Cpu Tweaker. Oct 08 10:59:58 volumio systemd[1]: Reached target Multi-User System. Oct 08 10:59:58 volumio systemd[1]: Reached target Graphical Interface. Oct 08 10:59:58 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Oct 08 10:59:58 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Oct 08 10:59:58 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Oct 08 10:59:58 volumio volumio-cpu-tweak[1231]: Setting RT Priority for mpd Oct 08 10:59:58 volumio volumio-cpu-tweak[1231]: pid 35's current scheduling policy: SCHED_OTHER Oct 08 10:59:58 volumio volumio-cpu-tweak[1231]: pid 35's current scheduling priority: 0 Oct 08 10:59:58 volumio volumio-cpu-tweak[1231]: Setting MPD Affinity Oct 08 10:59:58 volumio volumio-cpu-tweak[1231]: pid 3's current affinity mask: f Oct 08 10:59:58 volumio volumio-cpu-tweak[1231]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Oct 08 10:59:58 volumio volumio-cpu-tweak[1231]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Oct 08 10:59:58 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Oct 08 10:59:58 volumio volumio-remote-updater[626]: [2024-10-08 10:59:58] [info] asio async_connect error: system:111 (Connection refused) Oct 08 10:59:58 volumio volumio-remote-updater[626]: [2024-10-08 10:59:58] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Oct 08 10:59:58 volumio volumio-remote-updater[626]: [2024-10-08 10:59:58] [error] handle_connect error: Underlying Transport Error Oct 08 10:59:59 volumio ntpd[1191]: Soliciting pool server 217.144.138.234 Oct 08 11:00:00 volumio ntpd[1191]: Soliciting pool server 168.119.211.223 Oct 08 11:00:00 volumio ntpd[1191]: Deleting interface #4 wlan0, 169.254.27.195#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Oct 08 11:00:00 volumio ntpd[1191]: Soliciting pool server 194.164.164.175 Oct 08 11:00:00 volumio systemd[1]: apt-daily.service: Succeeded. Oct 08 11:00:00 volumio systemd[1]: Started Daily apt download activities. Oct 08 11:00:00 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Oct 08 11:00:00 volumio volumio[1230]: info: ------------------------------------------- Oct 08 11:00:00 volumio volumio[1230]: info: ----- Volumio3 ---- Oct 08 11:00:00 volumio volumio[1230]: info: ------------------------------------------- Oct 08 11:00:00 volumio volumio[1230]: info: ----- System startup ---- Oct 08 11:00:00 volumio volumio[1230]: info: ------------------------------------------- Oct 08 11:00:01 volumio ntpd[1191]: Soliciting pool server 162.159.200.123 Oct 08 11:00:01 volumio ntpd[1191]: Soliciting pool server 89.58.6.143 Oct 08 11:00:01 volumio ntpd[1191]: Soliciting pool server 131.188.3.223 Oct 08 11:00:01 volumio volumio[1230]: info: MYVOLUMIO Environment detected Oct 08 11:00:01 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 08 11:00:01 volumio systemd[1]: Started Daily apt upgrade and clean activities. Oct 08 11:00:01 volumio systemd[1]: Startup finished in 14.377s (kernel) + 34.103s (userspace) = 48.481s. Oct 08 11:00:01 volumio volumio[1230]: info: Plugin folders cleanup Oct 08 11:00:01 volumio volumio[1230]: info: Scanning into folder /volumio/app/plugins/ Oct 08 11:00:01 volumio volumio[1230]: info: Scanning category audio_interface Oct 08 11:00:01 volumio volumio[1230]: info: Scanning category miscellanea Oct 08 11:00:01 volumio volumio[1230]: info: Scanning category music_service Oct 08 11:00:01 volumio volumio[1230]: info: Scanning category plugins.json Oct 08 11:00:01 volumio volumio[1230]: info: Scanning category system_controller Oct 08 11:00:01 volumio volumio[1230]: info: Scanning category user_interface Oct 08 11:00:01 volumio volumio[1230]: info: Scanning into folder /data/plugins/ Oct 08 11:00:01 volumio volumio[1230]: info: Scanning category music_service Oct 08 11:00:01 volumio volumio[1230]: info: Scanning category user_interface Oct 08 11:00:01 volumio volumio[1230]: info: Plugin folders cleanup completed Oct 08 11:00:01 volumio volumio[1230]: info: ------------------------------------------- Oct 08 11:00:01 volumio volumio[1230]: info: ----- Core plugins startup ---- Oct 08 11:00:01 volumio volumio[1230]: info: ------------------------------------------- Oct 08 11:00:01 volumio volumio[1230]: info: Loading plugins from folder /volumio/app/plugins/ Oct 08 11:00:01 volumio volumio[1230]: info: Adding plugin upnp to MyMusic Plugins Oct 08 11:00:01 volumio volumio[1230]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 08 11:00:01 volumio volumio[1230]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 08 11:00:01 volumio volumio[1230]: info: Loading plugins from folder /data/plugins/ Oct 08 11:00:01 volumio volumio[1230]: info: Loading plugin "system"... Oct 08 11:00:01 volumio volumio[1230]: info: Loading plugin "appearance"... Oct 08 11:00:02 volumio ntpd[1191]: Soliciting pool server 185.244.195.159 Oct 08 11:00:02 volumio ntpd[1191]: Soliciting pool server 185.232.69.65 Oct 08 11:00:02 volumio ntpd[1191]: Soliciting pool server 116.203.98.67 Oct 08 11:00:02 volumio ntpd[1191]: Soliciting pool server 193.158.22.13 Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "network"... Oct 08 11:00:02 volumio volumio[1230]: info: Refreshing Cached IP Addresses Oct 08 11:00:02 volumio sudo[1354]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 08 11:00:02 volumio sudo[1354]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "services"... Oct 08 11:00:02 volumio sudo[1356]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 08 11:00:02 volumio sudo[1356]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "alsa_controller"... Oct 08 11:00:02 volumio sudo[1356]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:02 volumio sudo[1354]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:02 volumio sudo[1359]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 08 11:00:02 volumio sudo[1359]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:02 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "wizard"... Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "networkfs"... Oct 08 11:00:02 volumio volumio[1230]: info: Starting Udev Watcher for removable devices Oct 08 11:00:02 volumio volumio[1230]: info: Ignoring mount for partition: boot Oct 08 11:00:02 volumio volumio[1230]: info: Ignoring mount for partition: volumio Oct 08 11:00:02 volumio volumio[1230]: info: Ignoring mount for partition: volumio_data Oct 08 11:00:02 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "volumio_command_line_client"... Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "upnp"... Oct 08 11:00:02 volumio volumio[1230]: info: [1728378002849] Starting Upmpd Daemon Oct 08 11:00:02 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "my_music"... Oct 08 11:00:02 volumio volumio[1230]: info: Loading plugin "mpd"... Oct 08 11:00:03 volumio ntpd[1191]: Soliciting pool server 148.251.5.46 Oct 08 11:00:03 volumio ntpd[1191]: Soliciting pool server 54.36.110.36 Oct 08 11:00:03 volumio ntpd[1191]: Soliciting pool server 178.215.228.24 Oct 08 11:00:03 volumio volumio[1230]: info: Plugin upnp_browser is not enabled Oct 08 11:00:03 volumio volumio[1230]: info: Loading plugin "alarm-clock"... Oct 08 11:00:03 volumio volumio[1230]: info: Plugin airplay_emulation is not enabled Oct 08 11:00:03 volumio volumio[1230]: info: Loading plugin "last_100"... Oct 08 11:00:03 volumio volumio[1230]: info: Loading plugin "webradio"... Oct 08 11:00:03 volumio systemd[1]: systemd-fsckd.service: Succeeded. Oct 08 11:00:03 volumio volumio[1230]: info: Loading plugin "i2s_dacs"... Oct 08 11:00:03 volumio volumio[1230]: info: Loading plugin "volumiodiscovery"... Oct 08 11:00:03 volumio volumio[1230]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 08 11:00:03 volumio volumio[1230]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 08 11:00:03 volumio volumio[1230]: *** WARNING *** For more information see Oct 08 11:00:03 volumio node[1230]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 08 11:00:03 volumio volumio[1230]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 08 11:00:03 volumio volumio[1230]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 08 11:00:03 volumio volumio[1230]: *** WARNING *** For more information see Oct 08 11:00:03 volumio node[1230]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 08 11:00:03 volumio node[1230]: *** WARNING *** For more information see Oct 08 11:00:03 volumio node[1230]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 08 11:00:03 volumio node[1230]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 08 11:00:03 volumio node[1230]: *** WARNING *** For more information see Oct 08 11:00:03 volumio volumio[1230]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 08 11:00:03 volumio volumio[1230]: info: Discovery: Started advertising with name: Volumio Oct 08 11:00:03 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 08 11:00:03 volumio volumio[1230]: info: Loading plugin "jellyfin"... Oct 08 11:00:04 volumio ntpd[1191]: Soliciting pool server 176.9.157.155 Oct 08 11:00:04 volumio ntpd[1191]: Soliciting pool server 85.220.190.246 Oct 08 11:00:04 volumio volumio[1230]: info: Loading plugin "spop"... Oct 08 11:00:05 volumio ntpd[1191]: Soliciting pool server 185.11.138.90 Oct 08 11:00:05 volumio ntpd[1191]: Soliciting pool server 2a01:4f8:221:1acf::123 Oct 08 11:00:05 volumio volumio[1230]: info: Loading plugin "outputs"... Oct 08 11:00:05 volumio volumio[1230]: info: Loading plugin "albumart"... Oct 08 11:00:05 volumio volumio[1230]: info: Plugin example_plugin is not enabled Oct 08 11:00:05 volumio volumio[1230]: info: Loading plugin "inputs"... Oct 08 11:00:05 volumio volumio[1230]: info: Loading plugin "updater_comm"... Oct 08 11:00:05 volumio volumio[1230]: info: Plugin mpdemulation is not enabled Oct 08 11:00:05 volumio volumio[1230]: info: Loading plugin "rest_api"... Oct 08 11:00:05 volumio volumio[1230]: info: Loading plugin "websocket"... Oct 08 11:00:05 volumio volumio[1230]: info: Starting Socket.io Server version 2.3.0 Oct 08 11:00:05 volumio volumio[1230]: info: Loading plugin "Systeminfo"... Oct 08 11:00:05 volumio volumio[1230]: Forking 3 albumart workers Oct 08 11:00:05 volumio sudo[1359]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:05 volumio volumio[1230]: info: Loading i18n strings for locale de Oct 08 11:00:05 volumio volumio[1230]: Updating browse sources language Oct 08 11:00:05 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 08 11:00:06 volumio volumio[1230]: Starting albumart workers Oct 08 11:00:06 volumio volumio[1230]: Starting albumart workers Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::initPlayerControls Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: Express server listening on port 3000 Oct 08 11:00:06 volumio volumio[1230]: [Metrics] WebUI: 6s 184.03ms Oct 08 11:00:06 volumio volumio[1230]: Starting albumart workers Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::resetVolumioState Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::getcurrentVolume Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioRetrievevolume Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 11:00:06 volumio volumio[1230]: info: Discovery: Getting this device information Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 11:00:06 volumio volumio[1230]: info: Discovery: Getting this device information Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 08 11:00:06 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Oct 08 11:00:06 volumio volumio[1230]: info: Reloading queue from file Oct 08 11:00:06 volumio volumio[1230]: info: VolumeController:: Volume=70 Mute =false Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::pushState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::updateTrackBlock Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrackBlock Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioRetrievevolume Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::setRepeat null single undefined Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::pushState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::setRandom null Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::pushState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Oct 08 11:00:06 volumio volumio[1230]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 08 11:00:06 volumio volumio[1230]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03115 Oct 08 11:00:06 volumio volumio[1230]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 08 11:00:06 volumio volumio[1230]: verbose: New Socket.io Connection to 192.168.178.58:3000 from 192.168.178.22 UA: Dart/3.4 (dart:io) Engine version: 3 Transport: websocket Total Clients: 1 Oct 08 11:00:06 volumio volumio[1230]: info: Setting Device type: Raspberry PI Oct 08 11:00:06 volumio volumio[1230]: info: Completed loading Core Plugins Oct 08 11:00:06 volumio volumio[1230]: info: Preparing to generate the ALSA configuration file Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 08 11:00:06 volumio volumio[1230]: info: VolumeController:: Volume=70 Mute =false Oct 08 11:00:06 volumio volumio[1230]: info: CoreStateMachine::pushState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioPushState Oct 08 11:00:06 volumio volumio[1230]: info: Discovery: adding 42ccdd65-f6ff-457f-9e03-d6d78c1944cc Oct 08 11:00:06 volumio volumio[1230]: info: Discovery: Found device Volumio Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: Asound.conf file unchanged, so no further update is needed Oct 08 11:00:06 volumio volumio[1230]: info: Output device has changed, restarting MPD Oct 08 11:00:06 volumio sudo[1437]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 08 11:00:06 volumio volumio[1230]: info: ___________ START PLUGINS ___________ Oct 08 11:00:06 volumio sudo[1437]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:06 volumio volumio[1230]: info: ControllerMpd::onStart: Initializing MPD Oct 08 11:00:06 volumio volumio[1230]: info: Creating MPD Configuration file Oct 08 11:00:06 volumio sudo[1437]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:06 volumio sudo[1439]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 08 11:00:06 volumio sudo[1439]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:06 volumio sudo[1443]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 08 11:00:06 volumio sudo[1443]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 08 11:00:06 volumio volumio[1230]: info: [1728378006809] CoreMusicLibrary::Adding element Last_100 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 08 11:00:06 volumio sudo[1443]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 08 11:00:06 volumio volumio[1230]: info: [1728378006815] CoreMusicLibrary::Adding element Webradio Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 08 11:00:06 volumio volumio[1230]: info: Initializing BBC Radios Oct 08 11:00:06 volumio sudo[1445]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 08 11:00:06 volumio sudo[1445]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:06 volumio systemd[1]: Listening on mpd.socket. Oct 08 11:00:06 volumio systemd[1]: Starting Music Player Daemon... Oct 08 11:00:06 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 08 11:00:06 volumio systemd[1]: mpd.service: Succeeded. Oct 08 11:00:06 volumio systemd[1]: Stopped Music Player Daemon. Oct 08 11:00:06 volumio systemd[1]: Starting Music Player Daemon... Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 11:00:06 volumio volumio[1230]: info: Discovery: Getting this device information Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:06 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 08 11:00:06 volumio volumio[1230]: info: [1728378006896] CoreMusicLibrary::Adding element Jellyfin Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 08 11:00:06 volumio volumio[1230]: Cannot find translation for source Jellyfin Oct 08 11:00:06 volumio volumio[1230]: info: [jellyfin] Initialized plugin with device info: {"id":"42ccdd65-f6ff-457f-9e03-d6d78c1944cc","host":"http://192.168.178.51","name":"Volumio","type":"device","serviceName":"Volumio","state":{"status":"stop","volume":70,"mute":false,"artist":"MP3 (128 kbps)","track":"ROCK ANTENNE","albumart":"http://192.168.178.51/albumart"}} Oct 08 11:00:06 volumio volumio[1230]: info: Creating Spotify config file Oct 08 11:00:06 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:06 volumio volumio[1230]: info: Volumio Calling Home Oct 08 11:00:06 volumio sudo[1460]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 08 11:00:06 volumio sudo[1460]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:06 volumio sudo[1460]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Oct 08 11:00:06 volumio sudo[1460]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:07 volumio volumio[1230]: info: Discovery: this is already registered, 42ccdd65-f6ff-457f-9e03-d6d78c1944cc Oct 08 11:00:07 volumio volumio[1230]: info: Discovery: Found device Volumio Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:07 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:07 volumio volumio[1230]: info: MPD Permissions set Oct 08 11:00:07 volumio volumio[1230]: info: MPD Permissions set Oct 08 11:00:07 volumio volumio[1230]: info: Spotify config file written Oct 08 11:00:07 volumio volumio[1230]: 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 08 11:00:07 volumio volumio[1230]: info: Volumio called home Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio sudo[1467]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio sudo[1467]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 08 11:00:07 volumio systemd[1]: Started go-librespot Daemon. Oct 08 11:00:07 volumio go-librespot[1473]: Librespot-go daemon starting... Oct 08 11:00:07 volumio sudo[1467]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:07 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:07 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:07 volumio go-librespot[1473]: time="2024-10-08T11:00:07+02:00" level=info msg="generated new device id: 063a4fe563d47dd35b2084f0c05d35bef5735fe9" Oct 08 11:00:07 volumio go-librespot[1473]: time="2024-10-08T11:00:07+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 08 11:00:07 volumio go-librespot[1473]: time="2024-10-08T11:00:07+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 08 11:00:07 volumio go-librespot[1473]: time="2024-10-08T11:00:07+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 08 11:00:07 volumio go-librespot[1473]: time="2024-10-08T11:00:07+02:00" level=debug msg="zeroconf server listening on port 37931" Oct 08 11:00:08 volumio volumio-remote-updater[626]: [2024-10-08 11:00:08] [connect] Successful connection Oct 08 11:00:08 volumio volumio-remote-updater[626]: [2024-10-08 11:00:08] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1728378008 101 Oct 08 11:00:08 volumio volumio[1230]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 Oct 08 11:00:08 volumio mpd[1464]: Oct 08 11:00 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 08 11:00:08 volumio systemd[1]: Started Music Player Daemon. Oct 08 11:00:08 volumio sudo[1445]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:08 volumio sudo[1439]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:08 volumio volumio[1230]: info: Completed starting Core Plugins Oct 08 11:00:08 volumio volumio[1230]: info: ------------------------------------------- Oct 08 11:00:08 volumio volumio[1230]: info: ----- MyVolumio plugins startup ---- Oct 08 11:00:08 volumio volumio[1230]: info: ------------------------------------------- Oct 08 11:00:08 volumio volumio[1230]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 08 11:00:08 volumio volumio[1230]: error: MPD error: The expression evaluated to a falsy value: Oct 08 11:00:08 volumio volumio[1230]: assert.ok(self.idling) Oct 08 11:00:08 volumio volumio[1230]: error: The expression evaluated to a falsy value: Oct 08 11:00:08 volumio volumio[1230]: assert.ok(self.idling) Oct 08 11:00:08 volumio volumio[1230]: info: MPD running with PID1464 Oct 08 11:00:08 volumio volumio[1230]: ,establishing connection Oct 08 11:00:08 volumio volumio[1230]: error: MPD error: The expression evaluated to a falsy value: Oct 08 11:00:08 volumio volumio[1230]: assert.ok(self.idling) Oct 08 11:00:08 volumio volumio[1230]: error: The expression evaluated to a falsy value: Oct 08 11:00:08 volumio volumio[1230]: assert.ok(self.idling) Oct 08 11:00:08 volumio volumio[1230]: error: updateQueue error: null Oct 08 11:00:10 volumio volumio[1230]: info: go-librespot daemon successfully initialized Oct 08 11:00:10 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 08 11:00:10 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 08 11:00:10 volumio volumio[1230]: info: Discovery: Getting this device information Oct 08 11:00:10 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:10 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:10 volumio volumio[1230]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="obtained new client token: AABQvA6FPTV4JwYj3GQ25Em8O1p8vRLdCriN0LZ2XCAijqqdmqkCws/seuJm9IqqOINz85WLyb4EBwOSEj6Ipyjyf54Ibn+SUzn2VTfc/z8Hf65HL4nsUMQ3WoK0Eh8GyzmJNvecwjwTooxjJ3xTT0jCCxFn3tK1R3PaYBKwx46AIwXOSxjQQwxO1UzEZJCd0OhQ7FwFa20BhdKHwVQU0CNEr5m88t14ImhAxOLpRlACSZEvIoi82PpN" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="completed keyexchange" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="completed challenge" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="authenticated as danbosan1713" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="authenticated as danbosan1713" Oct 08 11:00:12 volumio sudo[1492]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 08 11:00:12 volumio sudo[1492]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:12 volumio sudo[1492]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:12 volumio sudo[1494]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 08 11:00:12 volumio sudo[1494]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:12 volumio sudo[1494]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:12 volumio sudo[1498]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 08 11:00:12 volumio sudo[1498]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="dealer connection opened" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=info msg="accepted zeroconf user danbosan1713 from SM-A528B" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="autoplay enabled: false" Oct 08 11:00:12 volumio go-librespot[1473]: time="2024-10-08T11:00:12+02:00" level=debug msg="received connection id: ZTljNGJlYzktYWY2YS00MTM2LWE4ZTktZGQzOTBhZTZhYTA1K2RlYWxlcit0Y3A6Ly8wYWNhNThhMS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNUE5RTY3ODBGRTYxN0VCMDA5MDRCNDkxOTJCMUJFOTFEOTdDRkM1NUM3REI0OUQ5MjNFOTIzNEYxNUU4NzZFMg==" Oct 08 11:00:12 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Oct 08 11:00:12 volumio sudo[1498]: pam_unix(sudo:session): session closed for user root Oct 08 11:00:12 volumio volumio[1230]: info: Upmpdcli Daemon Started Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 08 11:00:13 volumio volumio[1500]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="handling transfer player command from a6883923d5a41bb26b42240e42ab61b4269195bf" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="resolved context of track" uri="spotify:album:7gk5j9Ok764TbTsmkxthYt" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=trace msg="fetched new page 0 with 12 items (list: 12)" uri="spotify:album:7gk5j9Ok764TbTsmkxthYt" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="loading track (paused: false, position: 145005ms)" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio volumio[1230]: info: Initializing connection to go-librespot Websocket Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="new websocket client" Oct 08 11:00:13 volumio volumio[1230]: info: Connection to go-librespot Websocket established Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=trace msg="emitting websocket event: will_play" Oct 08 11:00:13 volumio volumio[1230]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:7jE9kifGTmYvyR6fD8aMX7","play_origin":"com.spotify.gaia"}} Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="selected format OGG_VORBIS_320 (f7339ec46d2c2b7c6e6c8d19d3f6d9f9e9a3b56a)" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="requested aes key for file f7339ec46d2c2b7c6e6c8d19d3f6d9f9e9a3b56a, gid: 7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1711" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="fetched first chunk of 20, total size is 10126625 bytes" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="fetched chunk 3/19, size: 524288" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1317" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="fetched chunk 1/19, size: 524288" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="fetched chunk 2/19, size: 524288" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="fetched chunk 13/19, size: 524288" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="fetched chunk 12/19, size: 524288" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="fetched chunk 15/19, size: 524288" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=trace msg="seek to 145005ms (diff: 61ms, samples: 6394720, bytes: 6486190)" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="fetched chunk 14/19, size: 524288" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:13 volumio volumio[1230]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 08 11:00:13 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=debug msg="created new output device" Oct 08 11:00:13 volumio go-librespot[1473]: time="2024-10-08T11:00:13+02:00" level=info msg="loaded track \"How Long\" (paused: false, position: 145005ms, duration: 229733ms, prefetched: false)" uri="spotify:track:7jE9kifGTmYvyR6fD8aMX7" Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=trace msg="scheduling prefetch in 55s" Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=trace msg="emitting websocket event: metadata" Oct 08 11:00:14 volumio volumio[1230]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7jE9kifGTmYvyR6fD8aMX7","name":"How Long","artist_names":["Dire Straits"],"album_name":"On Every Street","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ee92e1d463ee63440431179c","position":145005,"duration":229733,"release_date":"year:1991 month:9 day:10","track_number":12,"disc_number":1}} Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=trace msg="emitting websocket event: active" Oct 08 11:00:14 volumio volumio[1230]: SPOTIFY: received: {"type":"active","data":null} Oct 08 11:00:14 volumio volumio[1230]: info: Aligning Spotify Volume to Volumio Volume Oct 08 11:00:14 volumio volumio[1230]: info: CoreCommandRouter::volumioGetState Oct 08 11:00:14 volumio volumio[1230]: info: CorePlayQueue::getTrack 0 Oct 08 11:00:14 volumio volumio[1230]: info: Setting Spotify Volume from Volumio: 70 Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=debug msg="sending successful reply for dealer request" Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 08 11:00:14 volumio go-librespot[1473]: time="2024-10-08T11:00:14+02:00" level=trace msg="emitting websocket event: playing" Oct 08 11:00:14 volumio volumio[1230]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7jE9kifGTmYvyR6fD8aMX7","play_origin":"com.spotify.gaia"}} Oct 08 11:00:14 volumio volumio[1230]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 08 11:00:14 volumio volumio[1230]: TypeError: Cannot read property 'service' of undefined Oct 08 11:00:14 volumio volumio[1230]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Oct 08 11:00:14 volumio volumio[1230]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Oct 08 11:00:14 volumio volumio[1230]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Oct 08 11:00:14 volumio volumio[1230]: at WebSocket.emit (events.js:315:20) Oct 08 11:00:14 volumio volumio[1230]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 08 11:00:14 volumio volumio[1230]: at Receiver.emit (events.js:315:20) Oct 08 11:00:14 volumio volumio[1230]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 08 11:00:14 volumio volumio[1230]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 08 11:00:14 volumio volumio[1230]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 08 11:00:14 volumio volumio[1230]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 08 11:00:14 volumio volumio[1230]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 08 11:00:14 volumio sudo[1526]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-08 10:59 Oct 08 11:00:14 volumio sudo[1526]: 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"