-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Fri 2024-11-29 18:03:50 UTC. -- Nov 29 18:03:30 music-thingy systemd-timedated[957]: Changed local time to Fri Nov 29 18:03:30 2024 Nov 29 18:03:30 music-thingy sudo[955]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:30 music-thingy volumio-time-update[576]: volumio-time-update-util: System time updated successfully. Nov 29 18:03:30 music-thingy systemd[1]: Starting Daily apt download activities... Nov 29 18:03:30 music-thingy systemd[1]: Started Volumio Time Update Utility. Nov 29 18:03:30 music-thingy sudo[845]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:30 music-thingy wireless.js[606]: trying... Nov 29 18:03:30 music-thingy sudo[986]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 29 18:03:30 music-thingy sudo[986]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:30 music-thingy sudo[986]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:31 music-thingy wireless.js[606]: trying... Nov 29 18:03:31 music-thingy sudo[1003]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 29 18:03:31 music-thingy sudo[1003]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:31 music-thingy sudo[1003]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:31 music-thingy nmbd[728]: [2024/11/29 18:03:31.257108, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 29 18:03:31 music-thingy nmbd[728]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Nov 29 18:03:31 music-thingy systemd[1]: Started Samba NMB Daemon. Nov 29 18:03:31 music-thingy ntpd[751]: Listen normally on 3 eth0 192.168.0.184:123 Nov 29 18:03:31 music-thingy ntpd[751]: new interface(s) found: waking up resolver Nov 29 18:03:31 music-thingy systemd[1]: Starting Samba Winbind Daemon... Nov 29 18:03:31 music-thingy winbindd[1006]: [2024/11/29 18:03:31.479382, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Nov 29 18:03:31 music-thingy winbindd[1006]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Nov 29 18:03:31 music-thingy winbindd[1006]: [2024/11/29 18:03:31.493350, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 29 18:03:31 music-thingy systemd[1]: Started Samba Winbind Daemon. Nov 29 18:03:31 music-thingy winbindd[1006]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Nov 29 18:03:31 music-thingy systemd[1]: Starting Samba SMB Daemon... Nov 29 18:03:31 music-thingy smbd[1011]: [2024/11/29 18:03:31.879348, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 29 18:03:31 music-thingy systemd[1]: Started Samba SMB Daemon. Nov 29 18:03:31 music-thingy smbd[1011]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Nov 29 18:03:31 music-thingy volumio-remote-updater[581]: [2024-11-29 18:03:31] [info] asio async_connect error: system:111 (Connection refused) Nov 29 18:03:31 music-thingy volumio-remote-updater[581]: [2024-11-29 18:03:31] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Nov 29 18:03:31 music-thingy volumio-remote-updater[581]: [2024-11-29 18:03:31] [error] handle_connect error: Underlying Transport Error Nov 29 18:03:32 music-thingy systemd[1]: apt-daily.service: Succeeded. Nov 29 18:03:32 music-thingy systemd[1]: Started Daily apt download activities. Nov 29 18:03:32 music-thingy wireless.js[606]: trying... Nov 29 18:03:32 music-thingy sudo[1050]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 29 18:03:32 music-thingy sudo[1050]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:32 music-thingy systemd[1]: Starting Daily apt upgrade and clean activities... Nov 29 18:03:32 music-thingy sudo[1050]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:33 music-thingy wireless.js[606]: trying... Nov 29 18:03:33 music-thingy sudo[1094]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 29 18:03:33 music-thingy sudo[1094]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:33 music-thingy sudo[1094]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:33 music-thingy systemd[1]: apt-daily-upgrade.service: Succeeded. Nov 29 18:03:33 music-thingy systemd[1]: Started Daily apt upgrade and clean activities. Nov 29 18:03:33 music-thingy dhcpcd[979]: wlan0: leased 192.168.10.95 for 43200 seconds Nov 29 18:03:33 music-thingy avahi-daemon[604]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.10.95. Nov 29 18:03:33 music-thingy avahi-daemon[604]: New relevant interface wlan0.IPv4 for mDNS. Nov 29 18:03:33 music-thingy dhcpcd[979]: wlan0: adding route to 192.168.10.0/24 Nov 29 18:03:33 music-thingy avahi-daemon[604]: Registering new address record for 192.168.10.95 on wlan0.IPv4. Nov 29 18:03:33 music-thingy dhcpcd[979]: wlan0: adding default route via 192.168.10.1 Nov 29 18:03:34 music-thingy wireless.js[606]: trying... Nov 29 18:03:34 music-thingy sudo[1129]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Nov 29 18:03:34 music-thingy sudo[1129]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:34 music-thingy sudo[1129]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:34 music-thingy wireless.js[606]: Connected to: ----tehinternets Nov 29 18:03:34 music-thingy wireless.js[606]: ---- Nov 29 18:03:34 music-thingy sudo[1132]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 29 18:03:34 music-thingy sudo[1132]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:34 music-thingy sudo[1132]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:34 music-thingy wireless.js[606]: ... joined AP, wlan0 IPv4 is 192.168.10.95, ipV6 is undefined Nov 29 18:03:34 music-thingy wireless.js[606]: It's done! AP Nov 29 18:03:34 music-thingy kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Nov 29 18:03:34 music-thingy systemd[1]: Started Wireless Services. Nov 29 18:03:34 music-thingy systemd[1]: Started Volumio Backend Module. Nov 29 18:03:34 music-thingy systemd[1]: Started Volumio Cpu Tweaker. Nov 29 18:03:34 music-thingy systemd[1]: Reached target Multi-User System. Nov 29 18:03:34 music-thingy systemd[1]: Reached target Graphical Interface. Nov 29 18:03:34 music-thingy systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 29 18:03:34 music-thingy systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 29 18:03:34 music-thingy systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 29 18:03:34 music-thingy systemd[1]: Startup finished in 14.238s (kernel) + 22.060s (userspace) = 36.299s. Nov 29 18:03:34 music-thingy volumio-cpu-tweak[1138]: Setting RT Priority for mpd Nov 29 18:03:34 music-thingy volumio-cpu-tweak[1138]: Setting MPD Affinity Nov 29 18:03:34 music-thingy volumio-cpu-tweak[1138]: pid 781's current affinity mask: f Nov 29 18:03:34 music-thingy volumio-cpu-tweak[1138]: pid 781's new affinity mask: 3 Nov 29 18:03:34 music-thingy volumio-cpu-tweak[1138]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Nov 29 18:03:34 music-thingy volumio-cpu-tweak[1138]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Nov 29 18:03:34 music-thingy systemd[1]: volumio_cpu_tweak.service: Succeeded. Nov 29 18:03:35 music-thingy ntpd[751]: Listen normally on 4 wlan0 192.168.10.95:123 Nov 29 18:03:35 music-thingy ntpd[751]: new interface(s) found: waking up resolver Nov 29 18:03:36 music-thingy volumio[1137]: info: ------------------------------------------- Nov 29 18:03:36 music-thingy volumio[1137]: info: ----- Volumio3 ---- Nov 29 18:03:36 music-thingy volumio[1137]: info: ------------------------------------------- Nov 29 18:03:36 music-thingy volumio[1137]: info: ----- System startup ---- Nov 29 18:03:36 music-thingy volumio[1137]: info: ------------------------------------------- Nov 29 18:03:36 music-thingy volumio[1137]: info: MYVOLUMIO Environment detected Nov 29 18:03:36 music-thingy volumio[1137]: info: Plugin folders cleanup Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning into folder /volumio/app/plugins/ Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning category audio_interface Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning category miscellanea Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning category music_service Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning category plugins.json Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning category system_controller Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning category user_interface Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning into folder /data/plugins/ Nov 29 18:03:36 music-thingy volumio[1137]: info: Scanning category music_service Nov 29 18:03:36 music-thingy volumio[1137]: info: Plugin folders cleanup completed Nov 29 18:03:36 music-thingy volumio[1137]: info: ------------------------------------------- Nov 29 18:03:36 music-thingy volumio[1137]: info: ----- Core plugins startup ---- Nov 29 18:03:36 music-thingy volumio[1137]: info: ------------------------------------------- Nov 29 18:03:36 music-thingy volumio[1137]: info: Loading plugins from folder /volumio/app/plugins/ Nov 29 18:03:36 music-thingy volumio[1137]: info: Adding plugin upnp to MyMusic Plugins Nov 29 18:03:36 music-thingy volumio[1137]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 29 18:03:36 music-thingy volumio[1137]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 29 18:03:36 music-thingy volumio[1137]: info: Loading plugins from folder /data/plugins/ Nov 29 18:03:36 music-thingy volumio[1137]: info: Loading plugin "system"... Nov 29 18:03:36 music-thingy volumio[1137]: info: Loading plugin "appearance"... Nov 29 18:03:37 music-thingy volumio[1137]: info: Loading plugin "network"... Nov 29 18:03:37 music-thingy volumio[1137]: info: Refreshing Cached IP Addresses Nov 29 18:03:37 music-thingy sudo[1169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 29 18:03:37 music-thingy sudo[1169]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:37 music-thingy sudo[1169]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:37 music-thingy sudo[1171]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 29 18:03:37 music-thingy sudo[1171]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:37 music-thingy sudo[1171]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:37 music-thingy volumio[1137]: info: Loading plugin "services"... Nov 29 18:03:37 music-thingy volumio[1137]: info: Loading plugin "alsa_controller"... Nov 29 18:03:37 music-thingy sudo[1180]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Nov 29 18:03:37 music-thingy sudo[1180]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:37 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 29 18:03:37 music-thingy volumio[1137]: info: Loading plugin "wizard"... Nov 29 18:03:37 music-thingy volumio[1137]: info: Loading plugin "networkfs"... Nov 29 18:03:38 music-thingy volumio[1137]: info: Starting Udev Watcher for removable devices Nov 29 18:03:38 music-thingy sudo[1197]: 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.0.152/3f9dba47-c773-41db-b8f2-24591334b1db/media/music /mnt/NAS/music Nov 29 18:03:38 music-thingy sudo[1197]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:38 music-thingy volumio[1137]: info: Ignoring mount for partition: boot Nov 29 18:03:38 music-thingy volumio[1137]: info: Ignoring mount for partition: volumio Nov 29 18:03:38 music-thingy volumio[1137]: info: Ignoring mount for partition: volumio_data Nov 29 18:03:38 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "volumio_command_line_client"... Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "upnp"... Nov 29 18:03:38 music-thingy volumio[1137]: info: [1732903418072] Starting Upmpd Daemon Nov 29 18:03:38 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "my_music"... Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "mpd"... Nov 29 18:03:38 music-thingy kernel: Key type cifs.spnego registered Nov 29 18:03:38 music-thingy kernel: Key type cifs.idmap registered Nov 29 18:03:38 music-thingy kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Nov 29 18:03:38 music-thingy kernel: CIFS: Attempting to mount //192.168.0.152/3f9dba47-c773-41db-b8f2-24591334b1db/media/music Nov 29 18:03:38 music-thingy sudo[1197]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "upnp_browser"... Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "alarm-clock"... Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "airplay_emulation"... Nov 29 18:03:38 music-thingy volumio[1137]: info: Starting Shairport Sync Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "last_100"... Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "webradio"... Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "i2s_dacs"... Nov 29 18:03:38 music-thingy volumio[1137]: info: I2S DAC not set, start Auto-detection Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "volumiodiscovery"... Nov 29 18:03:38 music-thingy volumio[1137]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 29 18:03:38 music-thingy volumio[1137]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 29 18:03:38 music-thingy node[1137]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 29 18:03:38 music-thingy volumio[1137]: *** WARNING *** For more information see Nov 29 18:03:38 music-thingy volumio[1137]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 29 18:03:38 music-thingy volumio[1137]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 29 18:03:38 music-thingy volumio[1137]: *** WARNING *** For more information see Nov 29 18:03:38 music-thingy node[1137]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 29 18:03:38 music-thingy node[1137]: *** WARNING *** For more information see Nov 29 18:03:38 music-thingy node[1137]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 29 18:03:38 music-thingy node[1137]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 29 18:03:38 music-thingy node[1137]: *** WARNING *** For more information see Nov 29 18:03:38 music-thingy volumio[1137]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 29 18:03:38 music-thingy volumio[1137]: info: Discovery: Started advertising with name: Music-Thingy Nov 29 18:03:38 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 29 18:03:38 music-thingy volumio[1137]: info: Loading plugin "spop"... Nov 29 18:03:39 music-thingy sudo[1180]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:40 music-thingy volumio[1137]: info: Loading plugin "ytmusic"... Nov 29 18:03:40 music-thingy volumio[1137]: info: Loading plugin "outputs"... Nov 29 18:03:40 music-thingy volumio[1137]: info: Loading plugin "albumart"... Nov 29 18:03:40 music-thingy volumio[1137]: info: Plugin example_plugin is not enabled Nov 29 18:03:40 music-thingy volumio[1137]: info: Loading plugin "inputs"... Nov 29 18:03:40 music-thingy volumio[1137]: info: Loading plugin "updater_comm"... Nov 29 18:03:41 music-thingy volumio[1137]: info: Plugin mpdemulation is not enabled Nov 29 18:03:41 music-thingy volumio[1137]: info: Loading plugin "rest_api"... Nov 29 18:03:41 music-thingy volumio[1137]: info: Loading plugin "websocket"... Nov 29 18:03:41 music-thingy volumio[1137]: info: Starting Socket.io Server version 2.3.0 Nov 29 18:03:41 music-thingy volumio[1137]: Forking 3 albumart workers Nov 29 18:03:41 music-thingy volumio[1137]: info: Loading i18n strings for locale en Nov 29 18:03:41 music-thingy volumio[1137]: Updating browse sources language Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::initPlayerControls Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: Express server listening on port 3000 Nov 29 18:03:41 music-thingy volumio[1137]: [Metrics] WebUI: 5s 954.31ms Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::resetVolumioState Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::getcurrentVolume Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::volumioRetrievevolume Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 18:03:41 music-thingy volumio[1137]: info: Volumio Network Manager: Network status updated: 3 Nov 29 18:03:41 music-thingy volumio[1137]: info: Reloading queue from file Nov 29 18:03:41 music-thingy volumio[1137]: info: VolumeController:: Volume=100 Mute =false Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::pushState Nov 29 18:03:41 music-thingy volumio[1137]: info: CorePlayQueue::getTrack 0 Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::volumioPushState Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::updateTrackBlock Nov 29 18:03:41 music-thingy volumio[1137]: info: CorePlayQueue::getTrackBlock Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::volumioRetrievevolume Nov 29 18:03:41 music-thingy volumio[1137]: info: Setting Device type: Raspberry PI Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::setRepeat null single undefined Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::pushState Nov 29 18:03:41 music-thingy volumio[1137]: info: CorePlayQueue::getTrack 0 Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::volumioPushState Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::setRandom null Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::pushState Nov 29 18:03:41 music-thingy volumio[1137]: info: CorePlayQueue::getTrack 0 Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::volumioPushState Nov 29 18:03:41 music-thingy volumio[1137]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Nov 29 18:03:41 music-thingy volumio[1137]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03111 Nov 29 18:03:41 music-thingy volumio[1137]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Nov 29 18:03:41 music-thingy volumio[1137]: info: Completed loading Core Plugins Nov 29 18:03:41 music-thingy volumio[1137]: info: Preparing to generate the ALSA configuration file Nov 29 18:03:41 music-thingy volumio[1137]: Starting albumart workers Nov 29 18:03:41 music-thingy volumio[1137]: info: VolumeController:: Volume=100 Mute =false Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreStateMachine::pushState Nov 29 18:03:41 music-thingy volumio[1137]: info: CorePlayQueue::getTrack 0 Nov 29 18:03:41 music-thingy volumio[1137]: info: CoreCommandRouter::volumioPushState Nov 29 18:03:41 music-thingy volumio[1137]: info: Asound.conf file written Nov 29 18:03:41 music-thingy volumio[1137]: Starting albumart workers Nov 29 18:03:41 music-thingy sudo[1267]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Nov 29 18:03:41 music-thingy sudo[1267]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:41 music-thingy volumio-remote-updater[581]: [2024-11-29 18:03:41] [connect] Successful connection Nov 29 18:03:41 music-thingy sudo[1267]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:41 music-thingy volumio[1137]: Starting albumart workers Nov 29 18:03:41 music-thingy volumio[1137]: info: Output device has changed, restarting MPD Nov 29 18:03:41 music-thingy sudo[1272]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 29 18:03:41 music-thingy sudo[1272]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy volumio[1137]: info: Output device has changed, restarting Shairport Sync Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy sudo[1272]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 18:03:42 music-thingy sudo[1275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 29 18:03:42 music-thingy sudo[1275]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy volumio[1137]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 29 18:03:42 music-thingy volumio[1137]: info: ___________ START PLUGINS ___________ Nov 29 18:03:42 music-thingy volumio[1137]: info: ControllerMpd::onStart: Initializing MPD Nov 29 18:03:42 music-thingy volumio[1137]: info: Creating MPD Configuration file Nov 29 18:03:42 music-thingy systemd[1]: Stopping Music Player Daemon... Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 29 18:03:42 music-thingy volumio[1137]: info: [1732903422115] CoreMusicLibrary::Adding element Media Servers Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 29 18:03:42 music-thingy sudo[1283]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 29 18:03:42 music-thingy sudo[1283]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy sudo[1281]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 29 18:03:42 music-thingy sudo[1281]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy sudo[1281]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:42 music-thingy systemd[1]: mpd.service: Succeeded. Nov 29 18:03:42 music-thingy systemd[1]: Stopped Music Player Daemon. Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 18:03:42 music-thingy systemd[1]: Starting Music Player Daemon... Nov 29 18:03:42 music-thingy volumio[1137]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 29 18:03:42 music-thingy volumio[1137]: info: [1732903422323] CoreMusicLibrary::Adding element Last_100 Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 29 18:03:42 music-thingy volumio[1137]: info: [1732903422326] CoreMusicLibrary::Adding element Webradio Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 29 18:03:42 music-thingy volumio[1137]: info: Initializing BBC Radios Nov 29 18:03:42 music-thingy sudo[1286]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 29 18:03:42 music-thingy sudo[1286]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy sudo[1286]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: Creating Spotify config file Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 29 18:03:42 music-thingy volumio[1137]: info: [1732903422522] CoreMusicLibrary::Adding element YouTube Music Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 29 18:03:42 music-thingy volumio[1137]: Cannot find translation for source YouTube Music Nov 29 18:03:42 music-thingy volumio[1137]: info: Volumio Calling Home Nov 29 18:03:42 music-thingy volumio[1137]: info: Discovery: adding 20565ad2-be8d-424c-bb9e-c916971d41dc Nov 29 18:03:42 music-thingy volumio[1137]: info: Discovery: Found device Music-Thingy Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::volumioGetState Nov 29 18:03:42 music-thingy volumio[1137]: info: CorePlayQueue::getTrack 0 Nov 29 18:03:42 music-thingy volumio[1137]: info: Discovery: this is already registered, 20565ad2-be8d-424c-bb9e-c916971d41dc Nov 29 18:03:42 music-thingy volumio[1137]: info: Discovery: Found device Music-Thingy Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::volumioGetState Nov 29 18:03:42 music-thingy volumio[1137]: info: CorePlayQueue::getTrack 0 Nov 29 18:03:42 music-thingy volumio[1137]: info: MPD Permissions set Nov 29 18:03:42 music-thingy volumio[1137]: info: MPD Permissions set Nov 29 18:03:42 music-thingy volumio-remote-updater[581]: [2024-11-29 18:03:42] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732903421 101 Nov 29 18:03:42 music-thingy volumio[1137]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Nov 29 18:03:42 music-thingy volumio[1137]: info: Spotify config file written Nov 29 18:03:42 music-thingy sudo[1333]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 29 18:03:42 music-thingy sudo[1333]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy volumio[1137]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 29 18:03:42 music-thingy volumio[1137]: info: Volumio called home Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 18:03:42 music-thingy systemd[1]: Started go-librespot Daemon. Nov 29 18:03:42 music-thingy go-librespot[1335]: Librespot-go daemon starting... Nov 29 18:03:42 music-thingy sudo[1333]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:42 music-thingy volumio[1137]: info: Starting Shairport Sync Nov 29 18:03:42 music-thingy volumio[1137]: info: Starting Shairport Sync Nov 29 18:03:42 music-thingy volumio[1137]: info: Starting Shairport Sync Nov 29 18:03:42 music-thingy sudo[1346]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 29 18:03:42 music-thingy sudo[1346]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy sudo[1348]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 29 18:03:42 music-thingy sudo[1348]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy sudo[1353]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 29 18:03:42 music-thingy sudo[1353]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:42 music-thingy systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 29 18:03:42 music-thingy systemd[1]: shairport-sync.service: Succeeded. Nov 29 18:03:42 music-thingy systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 29 18:03:42 music-thingy volumio[1137]: info: CoreCommandRouter::volumioGetState Nov 29 18:03:42 music-thingy volumio[1137]: info: CorePlayQueue::getTrack 0 Nov 29 18:03:42 music-thingy systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 29 18:03:43 music-thingy sudo[1348]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:43 music-thingy sudo[1346]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:43 music-thingy systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 29 18:03:43 music-thingy systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Nov 29 18:03:43 music-thingy systemd[1]: shairport-sync.service: Succeeded. Nov 29 18:03:43 music-thingy systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 29 18:03:43 music-thingy systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 29 18:03:43 music-thingy volumio[1137]: info: Shairport-Sync Started Nov 29 18:03:43 music-thingy sudo[1353]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:43 music-thingy volumio[1137]: Error adding Membership: Error: addMembership EINVAL Nov 29 18:03:43 music-thingy volumio[1137]: info: Shairport-Sync Started Nov 29 18:03:43 music-thingy volumio[1137]: info: Shairport-Sync Started Nov 29 18:03:43 music-thingy volumio[1137]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 29 18:03:43 music-thingy volumio[1137]: SPOTIFY: BQB39tI2eRqOvKONnx-EsaOMbYOOvq8sj4yTkkPdYw0rDf1mMeLkB3eb0PJomwqTAvUTg9Tku63ldxyET9AdneUottplWk5yFO08-CDbKjt8XvOGCHPUlTeEGnwjOgKYJgcPYZw-EMSPcP0IWjDKILobzRMHTNxm8RhKEYcX_7OVyoximStjkN0QilvNki14aBqVTajP0irJ4vSC0MYZmYN4SVIW3FGXmInYmeOWdd2igFFRodTbsJTLBTvT Nov 29 18:03:43 music-thingy volumio[1137]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 29 18:03:43 music-thingy volumio[1137]: info: New Spotify access token = BQB39tI2eRqOvKONnx-EsaOMbYOOvq8sj4yTkkPdYw0rDf1mMeLkB3eb0PJomwqTAvUTg9Tku63ldxyET9AdneUottplWk5yFO08-CDbKjt8XvOGCHPUlTeEGnwjOgKYJgcPYZw-EMSPcP0IWjDKILobzRMHTNxm8RhKEYcX_7OVyoximStjkN0QilvNki14aBqVTajP0irJ4vSC0MYZmYN4SVIW3FGXmInYmeOWdd2igFFRodTbsJTLBTvT Nov 29 18:03:43 music-thingy volumio[1137]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 29 18:03:43 music-thingy go-librespot[1335]: time="2024-11-29T18:03:43Z" level=info msg="generated new device id: bf5bc67859b9751cde764255ea306b164ea94828" Nov 29 18:03:43 music-thingy go-librespot[1335]: time="2024-11-29T18:03:43Z" level=debug msg="stored credentials found for 11124932393" Nov 29 18:03:43 music-thingy mpd[1304]: Nov 29 18:03 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 29 18:03:43 music-thingy systemd[1]: Started Music Player Daemon. Nov 29 18:03:43 music-thingy sudo[1275]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:43 music-thingy sudo[1283]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:43 music-thingy volumio[1137]: info: Completed starting Core Plugins Nov 29 18:03:43 music-thingy volumio[1137]: info: ------------------------------------------- Nov 29 18:03:43 music-thingy volumio[1137]: info: ----- MyVolumio plugins startup ---- Nov 29 18:03:43 music-thingy volumio[1137]: info: ------------------------------------------- Nov 29 18:03:43 music-thingy volumio[1137]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 29 18:03:43 music-thingy volumio[1137]: error: MPD error: The expression evaluated to a falsy value: Nov 29 18:03:43 music-thingy volumio[1137]: assert.ok(self.idling) Nov 29 18:03:43 music-thingy volumio[1137]: error: The expression evaluated to a falsy value: Nov 29 18:03:43 music-thingy volumio[1137]: assert.ok(self.idling) Nov 29 18:03:43 music-thingy volumio[1137]: info: MPD running with PID1304 Nov 29 18:03:43 music-thingy volumio[1137]: ,establishing connection Nov 29 18:03:43 music-thingy volumio[1137]: error: updateQueue error: null Nov 29 18:03:43 music-thingy volumio[1137]: error: updateQueue error: null Nov 29 18:03:43 music-thingy volumio[1137]: SPOTIFY: User informations: {"country":"GB","display_name":"Darran Thomas","email":"darran311@yahoo.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11124932393"},"followers":{"href":null,"total":4},"href":"https://api.spotify.com/v1/users/11124932393","id":"11124932393","images":[{"height":300,"url":"https://scontent-bru2-1.xx.fbcdn.net/v/t39.30808-1/394033663_10232613008532379_6966504781300710621_n.jpg?stp=dst-jpg_s320x320&_nc_cat=110&ccb=1-7&_nc_sid=3e9727&_nc_ohc=ObQjUy42RdMQ7kNvgHcIXqp&_nc_zt=24&_nc_ht=scontent-bru2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=ARI1SA1AaZtN-tpnogKSqc1&oh=00_AYB2r-ayEJntapsCnXtenufda6I8kbMmItGpOo60wdn6Sw&oe=674FB933","width":300},{"height":64,"url":"https://scontent-bru2-1.xx.fbcdn.net/v/t39.30808-1/394033663_10232613008532379_6966504781300710621_n.jpg?stp=cp0_dst-jpg_s50x50&_nc_cat=110&ccb=1-7&_nc_sid=6738e8&_nc_ohc=ObQjUy42RdMQ7kNvgHcIXqp&_nc_zt=24&_nc_ht=scontent-bru2-1.xx&edm=AP4hL3IEAAAA&_nc_gid=ARI1SA1AaZtN-tpnogKSqc1&oh=00_AYDFYQ0UMZaU5Pxgnug-P_nHWN0tx8bkk4HRxNMFgYDNdg&oe=674FB933","width":64}],"product":"premium","type":"user","uri":"spotify:user:11124932393"} Nov 29 18:03:43 music-thingy volumio[1137]: info: Spotify Successfully logged in Nov 29 18:03:43 music-thingy volumio[1137]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 29 18:03:43 music-thingy volumio[1137]: info: [1732903423379] CoreMusicLibrary::Adding element Spotify Nov 29 18:03:43 music-thingy volumio[1137]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 29 18:03:43 music-thingy volumio[1137]: Cannot find translation for source YouTube Music Nov 29 18:03:43 music-thingy volumio[1137]: Cannot find translation for source Spotify Nov 29 18:03:43 music-thingy go-librespot[1335]: time="2024-11-29T18:03:43Z" level=debug msg="obtained new client token: AACAyOYiuLdaQmucy1GLxK9bIc79/l80JNLi4SdIS82CBHnWnqYvtfibxRHq8fEJ37tGnCqYHZ3IL7cximDJ3irLJ0lGEshUq08pamKV7qVTM8GVhotbylMGu7SoYhvNYeXCTNxZh1gqRfZg8nRW6fxx705Ysq1wmKbnbC2wjkmN05j0VW1NmChsc1uA7f7XBjWKWQ9HtFMlRuJVe4AedBi9ZHoquHlFvaH1bqdvtYfx9CbgP+bVrcHUxf4/" Nov 29 18:03:43 music-thingy go-librespot[1335]: time="2024-11-29T18:03:43Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 29 18:03:43 music-thingy go-librespot[1335]: time="2024-11-29T18:03:43Z" level=debug msg="completed keyexchange" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="completed challenge" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="authenticated as 11124932393" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="authenticated as 11124932393" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="dealer connection opened" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="received connection id: ZTFlNGI0OTYtNzIyMC00ZTVjLTg5ODMtNzkwMmJkYzlhNWI2K2RlYWxlcit0Y3A6Ly8wYWNhNDE3Ni5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArQjI4MzJDQ0JBQUI5NTVGNjgyNTY1NTk1NDA0OEIzMERDMjk1OEUyMjIyRDNBQTY0OTIxOEFCOTY1Nzg4RDhCNA==" Nov 29 18:03:44 music-thingy go-librespot[1335]: time="2024-11-29T18:03:44Z" level=debug msg="put connect state because NEW_DEVICE" Nov 29 18:03:45 music-thingy volumio[1137]: info: go-librespot daemon successfully initialized Nov 29 18:03:47 music-thingy systemd[1]: systemd-fsckd.service: Succeeded. Nov 29 18:03:48 music-thingy sudo[1387]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 29 18:03:48 music-thingy sudo[1387]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:48 music-thingy sudo[1387]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:48 music-thingy sudo[1389]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 29 18:03:48 music-thingy sudo[1389]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:48 music-thingy sudo[1389]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:48 music-thingy sudo[1393]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 29 18:03:48 music-thingy sudo[1393]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 18:03:48 music-thingy systemd[1]: Started UPnP Renderer front-end to MPD. Nov 29 18:03:48 music-thingy sudo[1393]: pam_unix(sudo:session): session closed for user root Nov 29 18:03:48 music-thingy volumio[1137]: info: Upmpdcli Daemon Started Nov 29 18:03:48 music-thingy volumio[1395]: Generating RSA private key, 4096 bit long modulus (2 primes) Nov 29 18:03:48 music-thingy volumio[1137]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 29 18:03:48 music-thingy go-librespot[1335]: time="2024-11-29T18:03:48Z" level=debug msg="handling transfer player command from 993590c032859e93728aad04b61c393b8632c7ea" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=trace msg="fetched new page 0 with 50 items (list: 50)" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="loading track spotify:track:1kPBT8S2wJFNAyBMnGVZgL (paused: true, position: 18062ms)" Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: Cannot compose Albumart path Nov 29 18:03:49 music-thingy volumio[1137]: info: Initializing connection to go-librespot Websocket Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="new websocket client" Nov 29 18:03:49 music-thingy volumio[1137]: info: Connection to go-librespot Websocket established Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=trace msg="emitting websocket event: will_play" Nov 29 18:03:49 music-thingy volumio[1137]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1kPBT8S2wJFNAyBMnGVZgL","play_origin":"playlist"}} Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:1kPBT8S2wJFNAyBMnGVZgL" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="requested aes key for file 6d640698a8a101ba1557c39064256390aa21fdf5, gid: 1kPBT8S2wJFNAyBMnGVZgL" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2797" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="fetched first chunk of 9, total size is 4607584 bytes" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="fetched chunk 3/8, size: 524288" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=trace msg="seek to 18062ms (diff: 179ms, samples: 796534, bytes: 518075)" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="fetched chunk 1/8, size: 524288" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=info msg="loaded track \"I'd Rather Go Blind\" (uri: spotify:track:1kPBT8S2wJFNAyBMnGVZgL, paused: true, position: 18062ms, duration: 156653ms)" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="fetched chunk 2/8, size: 524288" Nov 29 18:03:49 music-thingy go-librespot[1335]: time="2024-11-29T18:03:49Z" level=debug msg="fetched chunk 4/8, size: 524288" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1845" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=trace msg="emitting websocket event: metadata" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=trace msg="emitting websocket event: active" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="sending successful reply for delaer request" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 29 18:03:50 music-thingy volumio[1137]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1kPBT8S2wJFNAyBMnGVZgL","name":"I'd Rather Go Blind","artist_names":["Etta James"],"album_name":"Tell Mama","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027649604d1b27be1c78c466e9","position":18062,"duration":156653,"release_date":"year:1968 month:4 day:18","track_number":2,"disc_number":1}} Nov 29 18:03:50 music-thingy volumio[1137]: SPOTIFY: received: {"type":"active","data":null} Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 29 18:03:50 music-thingy volumio[1137]: info: Aligning Spotify Volume to Volumio Volume Nov 29 18:03:50 music-thingy volumio[1137]: info: CoreCommandRouter::volumioGetState Nov 29 18:03:50 music-thingy volumio[1137]: info: CorePlayQueue::getTrack 0 Nov 29 18:03:50 music-thingy volumio[1137]: info: Setting Spotify Volume from Volumio: 100 Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1845" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 29 18:03:50 music-thingy go-librespot[1335]: time="2024-11-29T18:03:50Z" level=trace msg="emitting websocket event: paused" Nov 29 18:03:50 music-thingy volumio[1137]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:1kPBT8S2wJFNAyBMnGVZgL","play_origin":"playlist"}} Nov 29 18:03:50 music-thingy volumio[1137]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 29 18:03:50 music-thingy volumio[1137]: TypeError: Cannot read property 'service' of undefined Nov 29 18:03:50 music-thingy volumio[1137]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Nov 29 18:03:50 music-thingy volumio[1137]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Nov 29 18:03:50 music-thingy volumio[1137]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Nov 29 18:03:50 music-thingy volumio[1137]: at WebSocket.emit (events.js:315:20) Nov 29 18:03:50 music-thingy volumio[1137]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Nov 29 18:03:50 music-thingy volumio[1137]: at Receiver.emit (events.js:315:20) Nov 29 18:03:50 music-thingy volumio[1137]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Nov 29 18:03:50 music-thingy volumio[1137]: at internal/process/task_queues.js:149:7 Nov 29 18:03:50 music-thingy volumio[1137]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Nov 29 18:03:50 music-thingy volumio[1137]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Nov 29 18:03:50 music-thingy volumio[1137]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Nov 29 18:03:50 music-thingy volumio[1137]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 29 18:03:50 music-thingy sudo[1421]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-29 18:02 Nov 29 18:03:50 music-thingy sudo[1421]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"