-- Logs begin at Thu 2019-02-14 15:41:59 IST, end at Fri 2025-06-06 19:35:13 IST. -- Jun 06 19:34:27 pallab systemd-timedated[994]: Changed local time to Fri Jun 6 19:34:27 2025 Jun 06 19:34:27 pallab sudo[992]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:27 pallab systemd[1]: Starting Daily apt download activities... Jun 06 19:34:27 pallab volumio-time-update[616]: volumio-time-update-util: System time updated successfully. Jun 06 19:34:27 pallab systemd[1]: Started Volumio Time Update Utility. Jun 06 19:34:27 pallab wireless.js[598]: trying... Jun 06 19:34:27 pallab sudo[1001]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:27 pallab sudo[1001]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:27 pallab sudo[1001]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:28 pallab wireless.js[598]: trying... Jun 06 19:34:28 pallab sudo[1018]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:28 pallab sudo[1018]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:28 pallab sudo[1018]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:28 pallab volumio-remote-updater[600]: [2025-06-06 19:34:28] [info] asio async_connect error: system:111 (Connection refused) Jun 06 19:34:28 pallab volumio-remote-updater[600]: [2025-06-06 19:34:28] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jun 06 19:34:28 pallab volumio-remote-updater[600]: [2025-06-06 19:34:28] [error] handle_connect error: Underlying Transport Error Jun 06 19:34:28 pallab systemd[1]: Started Samba NMB Daemon. Jun 06 19:34:28 pallab nmbd[759]: [2025/06/06 19:34:28.588508, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 06 19:34:28 pallab nmbd[759]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jun 06 19:34:28 pallab dhcpcd[906]: eth0: leased 192.168.0.158 for 7200 seconds Jun 06 19:34:28 pallab systemd[1]: Starting Samba Winbind Daemon... Jun 06 19:34:28 pallab dhcpcd[906]: eth0: adding route to 192.168.0.0/24 Jun 06 19:34:28 pallab dhcpcd[906]: eth0: adding default route via 192.168.0.1 Jun 06 19:34:28 pallab dhcpcd[906]: forked to background, child pid 1043 Jun 06 19:34:28 pallab sudo[905]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:29 pallab winbindd[1020]: [2025/06/06 19:34:29.101044, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jun 06 19:34:29 pallab winbindd[1020]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jun 06 19:34:29 pallab winbindd[1020]: [2025/06/06 19:34:29.123129, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 06 19:34:29 pallab systemd[1]: Started Samba Winbind Daemon. Jun 06 19:34:29 pallab winbindd[1020]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jun 06 19:34:29 pallab systemd[1]: Starting Samba SMB Daemon... Jun 06 19:34:29 pallab wireless.js[598]: trying... Jun 06 19:34:29 pallab sudo[1048]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:29 pallab sudo[1048]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:29 pallab sudo[1048]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:29 pallab wpa_supplicant[920]: wlan0: Trying to associate with SSID 'Pallab1979' Jun 06 19:34:29 pallab smbd[1049]: [2025/06/06 19:34:29.644653, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jun 06 19:34:29 pallab smbd[1049]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jun 06 19:34:29 pallab systemd[1]: Started Samba SMB Daemon. Jun 06 19:34:29 pallab dhcpcd[1043]: wlan0: carrier acquired Jun 06 19:34:29 pallab dhcpcd[1043]: wlan0: IAID eb:0d:b3:03 Jun 06 19:34:29 pallab dhcpcd[1043]: wlan0: adding address fe80::e471:3734:1f1e:5cc5 Jun 06 19:34:29 pallab dhcpcd[1043]: ipv6_addaddr1: Permission denied Jun 06 19:34:29 pallab dhcpcd[1043]: wlan0: carrier lost Jun 06 19:34:29 pallab wpa_supplicant[920]: wlan0: Associated with 60:a4:b7:81:63:f3 Jun 06 19:34:29 pallab wpa_supplicant[920]: wlan0: CTRL-EVENT-CONNECTED - Connection to 60:a4:b7:81:63:f3 completed [id=0 id_str=] Jun 06 19:34:29 pallab wpa_supplicant[920]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jun 06 19:34:29 pallab dhcpcd[1043]: wlan0: carrier acquired Jun 06 19:34:29 pallab dhcpcd[1043]: wlan0: connected to Access Point `Pallab1979' Jun 06 19:34:29 pallab dhcpcd[1043]: wlan0: IAID eb:0d:b3:03 Jun 06 19:34:29 pallab dhcpcd[1043]: wlan0: soliciting a DHCP lease Jun 06 19:34:30 pallab wireless.js[598]: trying... Jun 06 19:34:30 pallab sudo[1105]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:30 pallab sudo[1105]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:30 pallab sudo[1105]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:30 pallab systemd[1]: apt-daily.service: Succeeded. Jun 06 19:34:30 pallab systemd[1]: Started Daily apt download activities. Jun 06 19:34:30 pallab dhcpcd[1043]: wlan0: soliciting an IPv6 router Jun 06 19:34:30 pallab systemd[1]: Starting Daily apt upgrade and clean activities... Jun 06 19:34:31 pallab wireless.js[598]: trying... Jun 06 19:34:31 pallab sudo[1130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:31 pallab sudo[1130]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:31 pallab sudo[1130]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:31 pallab systemd[1]: apt-daily-upgrade.service: Succeeded. Jun 06 19:34:31 pallab systemd[1]: Started Daily apt upgrade and clean activities. Jun 06 19:34:32 pallab wireless.js[598]: trying... Jun 06 19:34:32 pallab sudo[1162]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:32 pallab sudo[1162]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:32 pallab sudo[1162]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:32 pallab dhcpcd[1043]: wlan0: offered 192.168.0.175 from 192.168.0.1 Jun 06 19:34:32 pallab dhcpcd[1043]: wlan0: probing address 192.168.0.175/24 Jun 06 19:34:33 pallab wireless.js[598]: trying... Jun 06 19:34:33 pallab sudo[1165]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:33 pallab sudo[1165]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:33 pallab sudo[1165]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:34 pallab wireless.js[598]: trying... Jun 06 19:34:34 pallab sudo[1168]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:34 pallab sudo[1168]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:34 pallab sudo[1168]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:35 pallab wireless.js[598]: trying... Jun 06 19:34:35 pallab sudo[1171]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:35 pallab sudo[1171]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:35 pallab sudo[1171]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:36 pallab wireless.js[598]: trying... Jun 06 19:34:36 pallab sudo[1174]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:36 pallab sudo[1174]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:36 pallab sudo[1174]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:37 pallab wireless.js[598]: trying... Jun 06 19:34:37 pallab sudo[1177]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:37 pallab sudo[1177]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:37 pallab sudo[1177]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:37 pallab dhcpcd[1043]: wlan0: leased 192.168.0.175 for 7200 seconds Jun 06 19:34:37 pallab avahi-daemon[611]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.175. Jun 06 19:34:37 pallab avahi-daemon[611]: New relevant interface wlan0.IPv4 for mDNS. Jun 06 19:34:37 pallab dhcpcd[1043]: wlan0: adding route to 192.168.0.0/24 Jun 06 19:34:37 pallab avahi-daemon[611]: Registering new address record for 192.168.0.175 on wlan0.IPv4. Jun 06 19:34:37 pallab dhcpcd[1043]: wlan0: adding default route via 192.168.0.1 Jun 06 19:34:38 pallab wireless.js[598]: trying... Jun 06 19:34:38 pallab sudo[1200]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwgetid -r Jun 06 19:34:38 pallab sudo[1200]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:38 pallab sudo[1200]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:38 pallab wireless.js[598]: Connected to: ----Pallab1979 Jun 06 19:34:38 pallab wireless.js[598]: ---- Jun 06 19:34:38 pallab sudo[1203]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 06 19:34:38 pallab sudo[1203]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:38 pallab sudo[1203]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:38 pallab wireless.js[598]: ... joined AP, wlan0 IPv4 is 192.168.0.175, ipV6 is undefined Jun 06 19:34:38 pallab wireless.js[598]: It's done! AP Jun 06 19:34:38 pallab systemd[1]: Started Wireless Services. Jun 06 19:34:38 pallab kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Jun 06 19:34:38 pallab systemd[1]: Started Volumio Backend Module. Jun 06 19:34:38 pallab systemd[1]: Started Volumio Cpu Tweaker. Jun 06 19:34:38 pallab systemd[1]: Reached target Multi-User System. Jun 06 19:34:38 pallab systemd[1]: Reached target Graphical Interface. Jun 06 19:34:38 pallab systemd[1]: Starting Update UTMP about System Runlevel Changes... Jun 06 19:34:38 pallab systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jun 06 19:34:38 pallab systemd[1]: Started Update UTMP about System Runlevel Changes. Jun 06 19:34:38 pallab systemd[1]: Startup finished in 13.198s (kernel) + 27.939s (userspace) = 41.137s. Jun 06 19:34:38 pallab volumio-cpu-tweak[1209]: Setting RT Priority for mpd Jun 06 19:34:38 pallab volumio-cpu-tweak[1209]: Setting MPD Affinity Jun 06 19:34:38 pallab volumio-cpu-tweak[1209]: pid 832's current affinity mask: 1 Jun 06 19:34:38 pallab volumio-cpu-tweak[1209]: pid 832's new affinity mask: 1 Jun 06 19:34:38 pallab volumio-cpu-tweak[1209]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Jun 06 19:34:38 pallab volumio-cpu-tweak[1209]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Jun 06 19:34:38 pallab systemd[1]: volumio_cpu_tweak.service: Succeeded. Jun 06 19:34:38 pallab volumio-remote-updater[600]: [2025-06-06 19:34:38] [info] asio async_connect error: system:111 (Connection refused) Jun 06 19:34:38 pallab volumio-remote-updater[600]: [2025-06-06 19:34:38] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Jun 06 19:34:38 pallab volumio-remote-updater[600]: [2025-06-06 19:34:38] [error] handle_connect error: Underlying Transport Error Jun 06 19:34:38 pallab ntpd[800]: Listen normally on 4 wlan0 192.168.0.175:123 Jun 06 19:34:38 pallab ntpd[800]: new interface(s) found: waking up resolver Jun 06 19:34:40 pallab volumio[1208]: info: ------------------------------------------- Jun 06 19:34:40 pallab volumio[1208]: info: ----- Volumio3 ---- Jun 06 19:34:40 pallab volumio[1208]: info: ------------------------------------------- Jun 06 19:34:40 pallab volumio[1208]: info: ----- System startup ---- Jun 06 19:34:40 pallab volumio[1208]: info: ------------------------------------------- Jun 06 19:34:41 pallab volumio[1208]: info: MYVOLUMIO Environment detected Jun 06 19:34:42 pallab volumio[1208]: info: Plugin folders cleanup Jun 06 19:34:42 pallab volumio[1208]: info: Scanning into folder /volumio/app/plugins/ Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category audio_interface Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category miscellanea Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category music_service Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category plugins.json Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category system_controller Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category user_interface Jun 06 19:34:42 pallab volumio[1208]: info: Scanning into folder /data/plugins/ Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category audio_interface Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category music_service Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category system_controller Jun 06 19:34:42 pallab volumio[1208]: info: Scanning category system_hardware Jun 06 19:34:42 pallab volumio[1208]: info: Plugin folders cleanup completed Jun 06 19:34:42 pallab volumio[1208]: info: ------------------------------------------- Jun 06 19:34:42 pallab volumio[1208]: info: ----- Core plugins startup ---- Jun 06 19:34:42 pallab volumio[1208]: info: ------------------------------------------- Jun 06 19:34:42 pallab volumio[1208]: info: Loading plugins from folder /volumio/app/plugins/ Jun 06 19:34:42 pallab volumio[1208]: info: Adding plugin upnp to MyMusic Plugins Jun 06 19:34:42 pallab volumio[1208]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 06 19:34:42 pallab volumio[1208]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 06 19:34:42 pallab volumio[1208]: info: Loading plugins from folder /data/plugins/ Jun 06 19:34:42 pallab volumio[1208]: info: Loading plugin "system"... Jun 06 19:34:42 pallab volumio[1208]: info: Loading plugin "appearance"... Jun 06 19:34:43 pallab systemd[1]: systemd-fsckd.service: Succeeded. Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "network"... Jun 06 19:34:43 pallab volumio[1208]: info: Refreshing Cached IP Addresses Jun 06 19:34:43 pallab sudo[1243]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 06 19:34:43 pallab sudo[1243]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:43 pallab sudo[1245]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 06 19:34:43 pallab sudo[1245]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:43 pallab sudo[1243]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:43 pallab sudo[1245]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "services"... Jun 06 19:34:43 pallab sudo[1254]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 06 19:34:43 pallab sudo[1254]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "alsa_controller"... Jun 06 19:34:43 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "wizard"... Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "networkfs"... Jun 06 19:34:43 pallab volumio[1208]: info: Starting Udev Watcher for removable devices Jun 06 19:34:43 pallab volumio[1208]: info: Ignoring mount for partition: boot Jun 06 19:34:43 pallab volumio[1208]: info: Ignoring mount for partition: volumio Jun 06 19:34:43 pallab volumio[1208]: info: Ignoring mount for partition: volumio_data Jun 06 19:34:43 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "volumio_command_line_client"... Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "upnp"... Jun 06 19:34:43 pallab volumio[1208]: info: [1749218683859] Starting Upmpd Daemon Jun 06 19:34:43 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "my_music"... Jun 06 19:34:43 pallab volumio[1208]: info: Loading plugin "mpd"... Jun 06 19:34:44 pallab volumio[1208]: info: Loading plugin "upnp_browser"... Jun 06 19:34:44 pallab volumio[1208]: info: Loading plugin "alarm-clock"... Jun 06 19:34:44 pallab volumio[1208]: info: Loading plugin "airplay_emulation"... Jun 06 19:34:45 pallab volumio[1208]: info: Starting Shairport Sync Jun 06 19:34:45 pallab volumio[1208]: info: Loading plugin "last_100"... Jun 06 19:34:45 pallab volumio[1208]: info: Loading plugin "webradio"... Jun 06 19:34:45 pallab volumio[1208]: info: Loading plugin "i2s_dacs"... Jun 06 19:34:45 pallab volumio[1208]: info: Loading plugin "volumiodiscovery"... Jun 06 19:34:45 pallab volumio[1208]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 06 19:34:45 pallab volumio[1208]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 06 19:34:45 pallab volumio[1208]: *** WARNING *** For more information see Jun 06 19:34:45 pallab volumio[1208]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 06 19:34:45 pallab node[1208]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 06 19:34:45 pallab volumio[1208]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 06 19:34:45 pallab volumio[1208]: *** WARNING *** For more information see Jun 06 19:34:45 pallab node[1208]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 06 19:34:45 pallab node[1208]: *** WARNING *** For more information see Jun 06 19:34:45 pallab node[1208]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 06 19:34:45 pallab node[1208]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 06 19:34:45 pallab node[1208]: *** WARNING *** For more information see Jun 06 19:34:45 pallab volumio[1208]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 06 19:34:45 pallab volumio[1208]: info: Discovery: Started advertising with name: Pallab Jun 06 19:34:45 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 06 19:34:45 pallab volumio[1208]: info: Loading plugin "spop"... Jun 06 19:34:46 pallab volumio[1208]: info: Loading plugin "youtube2"... Jun 06 19:34:47 pallab sudo[1254]: pam_unix(sudo:session): session closed for user root Jun 06 19:34:47 pallab systemd[1]: systemd-hostnamed.service: Succeeded. Jun 06 19:34:48 pallab volumio-remote-updater[600]: [2025-06-06 19:34:48] [connect] Successful connection Jun 06 19:34:50 pallab volumio[1208]: info: Loading plugin "ytcr"... Jun 06 19:34:56 pallab volumio[1208]: info: Loading plugin "ytmusic"... Jun 06 19:34:57 pallab systemd[1]: systemd-timedated.service: Succeeded. Jun 06 19:34:59 pallab volumio[1208]: info: Loading plugin "autostart"... Jun 06 19:34:59 pallab volumio[1208]: info: Applying required configuration parameters for plugin autostart Jun 06 19:34:59 pallab volumio[1208]: info: AutoStart - onVolumioStart - read config.json Jun 06 19:34:59 pallab volumio[1208]: info: Loading plugin "outputs"... Jun 06 19:34:59 pallab volumio[1208]: info: Loading plugin "albumart"... Jun 06 19:34:59 pallab volumio[1208]: info: Plugin example_plugin is not enabled Jun 06 19:34:59 pallab volumio[1208]: info: Loading plugin "inputs"... Jun 06 19:34:59 pallab volumio[1208]: info: Loading plugin "updater_comm"... Jun 06 19:35:00 pallab volumio[1208]: info: Plugin mpdemulation is not enabled Jun 06 19:35:00 pallab volumio[1208]: info: Loading plugin "rest_api"... Jun 06 19:35:00 pallab volumio[1208]: info: Loading plugin "websocket"... Jun 06 19:35:00 pallab volumio[1208]: info: Starting Socket.io Server version 2.3.0 Jun 06 19:35:00 pallab volumio[1208]: info: Loading plugin "mpdoutput"... Jun 06 19:35:00 pallab volumio[1208]: Forking 3 albumart workers Jun 06 19:35:00 pallab volumio[1208]: info: Loading plugin "audiophonicsonoff"... Jun 06 19:35:01 pallab volumio[1208]: info: Applying required configuration parameters for plugin audiophonicsonoff Jun 06 19:35:01 pallab volumio[1208]: info: Audiophonics on/off initiated Jun 06 19:35:01 pallab volumio[1208]: info: Loading plugin "music_services_shield"... Jun 06 19:35:01 pallab volumio[1208]: info: Applying required configuration parameters for plugin music_services_shield Jun 06 19:35:01 pallab volumio[1208]: info: Loading plugin "pirateaudio"... Jun 06 19:35:01 pallab volumio[1208]: Starting albumart workers Jun 06 19:35:01 pallab volumio[1208]: info: Applying required configuration parameters for plugin pirateaudio Jun 06 19:35:01 pallab volumio[1208]: info: Loading i18n strings for locale en Jun 06 19:35:01 pallab volumio[1208]: Updating browse sources language Jun 06 19:35:01 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 06 19:35:01 pallab volumio[1208]: Starting albumart workers Jun 06 19:35:01 pallab volumio[1208]: Starting albumart workers Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::initPlayerControls Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: Express server listening on port 3000 Jun 06 19:35:02 pallab volumio[1208]: [Metrics] WebUI: 22s 155.84ms Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::resetVolumioState Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::getcurrentVolume Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::volumioRetrievevolume Jun 06 19:35:02 pallab sudo[1339]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 06 19:35:02 pallab sudo[1339]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:02 pallab sudo[1341]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 06 19:35:02 pallab sudo[1341]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:02 pallab sudo[1339]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:02 pallab sudo[1341]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:02 pallab volumio[1208]: info: Volumio Network Manager: Network status updated: 3 Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::pushState Jun 06 19:35:02 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::volumioPushState Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::updateTrackBlock Jun 06 19:35:02 pallab volumio[1208]: info: CorePlayQueue::getTrackBlock Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::volumioRetrievevolume Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::pushState Jun 06 19:35:02 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::volumioPushState Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: Reloading queue from file Jun 06 19:35:02 pallab volumio[1208]: info: Setting Device type: Raspberry PI Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::setRepeat null single undefined Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::pushState Jun 06 19:35:02 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::volumioPushState Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::setRandom null Jun 06 19:35:02 pallab volumio[1208]: info: CoreStateMachine::pushState Jun 06 19:35:02 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::volumioPushState Jun 06 19:35:02 pallab volumio[1208]: info: Completed loading Core Plugins Jun 06 19:35:02 pallab volumio[1208]: info: Preparing to generate the ALSA configuration file Jun 06 19:35:02 pallab volumio[1208]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jun 06 19:35:02 pallab volumio[1208]: info: Reading ALSA contributions from plugins. Jun 06 19:35:02 pallab sudo[1373]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 06 19:35:02 pallab sudo[1373]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:02 pallab volumio[1208]: info: Asound.conf file unchanged, so no further update is needed Jun 06 19:35:02 pallab volumio[1208]: info: Output device has changed, restarting MPD Jun 06 19:35:02 pallab sudo[1376]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 06 19:35:02 pallab sudo[1376]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:02 pallab systemd[1]: Started UPnP Renderer front-end to MPD. Jun 06 19:35:02 pallab volumio[1208]: info: Output device has changed, restarting Shairport Sync Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 06 19:35:02 pallab sudo[1376]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:02 pallab sudo[1380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 06 19:35:02 pallab sudo[1380]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:02 pallab sudo[1373]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:02 pallab systemd[1]: musicservicesshield.service: Succeeded. Jun 06 19:35:02 pallab systemd[1]: Stopped Shield Volumio Music Services in the User CPU Set. Jun 06 19:35:02 pallab systemd[1]: Stopping Shield Volumio Music Services in the User CPU Set... Jun 06 19:35:02 pallab systemd[1]: Stopping Music Player Daemon... Jun 06 19:35:02 pallab volumio[1208]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 06 19:35:02 pallab volumio[1208]: info: ___________ START PLUGINS ___________ Jun 06 19:35:02 pallab volumio[1208]: info: ControllerMpd::onStart: Initializing MPD Jun 06 19:35:02 pallab volumio[1208]: info: Creating MPD Configuration file Jun 06 19:35:02 pallab sudo[1386]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 06 19:35:02 pallab sudo[1386]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:02 pallab sudo[1386]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 06 19:35:02 pallab volumio[1208]: info: [1749218702911] CoreMusicLibrary::Adding element Media Servers Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 06 19:35:02 pallab sudo[1389]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 06 19:35:02 pallab sudo[1389]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:02 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 06 19:35:02 pallab systemd[1]: mpd.service: Succeeded. Jun 06 19:35:02 pallab systemd[1]: Stopped Music Player Daemon. Jun 06 19:35:03 pallab volumio[1208]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 06 19:35:03 pallab systemd[1]: Starting Music Player Daemon... Jun 06 19:35:03 pallab volumio[1208]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 06 19:35:03 pallab volumio[1208]: info: [1749218703060] CoreMusicLibrary::Adding element Last_100 Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 06 19:35:03 pallab volumio[1208]: info: [1749218703063] CoreMusicLibrary::Adding element Webradio Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 06 19:35:03 pallab volumio[1208]: info: Initializing BBC Radios Jun 06 19:35:03 pallab sudo[1392]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 06 19:35:03 pallab sudo[1392]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 06 19:35:03 pallab sudo[1392]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:03 pallab volumio[1208]: info: Creating Spotify config file Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 06 19:35:03 pallab volumio[1208]: info: [1749218703196] CoreMusicLibrary::Adding element YouTube2 Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 06 19:35:03 pallab volumio[1208]: Cannot find translation for source YouTube2 Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 06 19:35:03 pallab volumio[1208]: info: [1749218703252] CoreMusicLibrary::Adding element YouTube Music Jun 06 19:35:03 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 06 19:35:03 pallab volumio[1208]: Cannot find translation for source YouTube2 Jun 06 19:35:03 pallab volumio[1208]: Cannot find translation for source YouTube Music Jun 06 19:35:03 pallab volumio[1208]: info: AutoStart - onStart Jun 06 19:35:03 pallab volumio[1208]: info: Configuring GPIO pins Jun 06 19:35:03 pallab volumio[1208]: info: Soft shutdown GPIO 516 binding... OK Jun 06 19:35:03 pallab volumio[1208]: error: Plugin audiophonicsonoff failed to start! Error: EBUSY: resource busy or locked, write Jun 06 19:35:03 pallab volumio-remote-updater[600]: [2025-06-06 19:35:03] [connect] Successful connection Jun 06 19:35:03 pallab volumio[1208]: info: Volumio Calling Home Jun 06 19:35:03 pallab sudo[1454]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start pirateaudio.service Jun 06 19:35:03 pallab sudo[1454]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:03 pallab systemd[1]: Started Service for using pirate audio display in volumio. Jun 06 19:35:03 pallab sudo[1454]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:03 pallab sudo[1452]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh Jun 06 19:35:03 pallab sudo[1452]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:04 pallab volumio[1208]: info: Discovery: adding 2b11f12e-a9e9-4ec1-a77b-edb156aca7f6 Jun 06 19:35:04 pallab volumio[1208]: info: Discovery: Found device Pallab Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::volumioGetState Jun 06 19:35:04 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:04 pallab volumio[1208]: info: Discovery: this is already registered, 2b11f12e-a9e9-4ec1-a77b-edb156aca7f6 Jun 06 19:35:04 pallab volumio[1208]: info: Discovery: Found device Pallab Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::volumioGetState Jun 06 19:35:04 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:04 pallab volumio[1208]: info: Pirate audio service (daemon) started Jun 06 19:35:04 pallab volumio[1208]: info: MPD Permissions set Jun 06 19:35:04 pallab volumio[1208]: info: MPD Permissions set Jun 06 19:35:04 pallab volumio[1208]: info: Upmpdcli Daemon Started Jun 06 19:35:04 pallab volumio-remote-updater[600]: [2025-06-06 19:35:04] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1749218703 101 Jun 06 19:35:04 pallab volumio[1208]: 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 Jun 06 19:35:04 pallab volumio[1208]: info: Spotify config file written Jun 06 19:35:04 pallab volumio[1208]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab sudo[1486]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 06 19:35:04 pallab sudo[1486]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1458]: Traceback (most recent call last): Jun 06 19:35:04 pallab volumio[1458]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 13, in Jun 06 19:35:04 pallab volumio[1458]: import ST7789 # v0.0.6 Jun 06 19:35:04 pallab volumio[1458]: ModuleNotFoundError: No module named 'ST7789' Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 06 19:35:04 pallab volumio[1208]: info: No need to fix Spotify hosts Jun 06 19:35:04 pallab systemd[1]: Started go-librespot Daemon. Jun 06 19:35:04 pallab go-librespot[1497]: go-librespot daemon starting... Jun 06 19:35:04 pallab sudo[1486]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:04 pallab systemd[1]: pirateaudio.service: Main process exited, code=exited, status=1/FAILURE Jun 06 19:35:04 pallab systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Jun 06 19:35:04 pallab volumio[1208]: info: Volumio called home Jun 06 19:35:04 pallab sudo[1452]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:04 pallab volumio[1208]: info: Starting Shairport Sync Jun 06 19:35:04 pallab volumio[1208]: info: Starting Shairport Sync Jun 06 19:35:04 pallab mpd[1409]: Jun 06 19:35 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 06 19:35:04 pallab systemd[1]: pirateaudio.service: Service RestartSec=100ms expired, scheduling restart. Jun 06 19:35:04 pallab systemd[1]: pirateaudio.service: Scheduled restart job, restart counter is at 1. Jun 06 19:35:04 pallab systemd[1]: Started Music Player Daemon. Jun 06 19:35:04 pallab sudo[1509]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 06 19:35:04 pallab sudo[1389]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:04 pallab sudo[1380]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:04 pallab sudo[1509]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:04 pallab volumio[1208]: info: Starting Shairport Sync Jun 06 19:35:04 pallab sudo[1514]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 06 19:35:04 pallab sudo[1514]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:04 pallab volumio[1208]: info: CoreCommandRouter::volumioGetState Jun 06 19:35:04 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:04 pallab sudo[1517]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 06 19:35:04 pallab sudo[1517]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:04 pallab volumio[1208]: Upnp client error: Error: This socket has been ended by the other party Jun 06 19:35:04 pallab systemd[1]: Starting Shield Volumio Music Services in the User CPU Set... Jun 06 19:35:04 pallab systemd[1]: Stopped Service for using pirate audio display in volumio. Jun 06 19:35:04 pallab systemd[1]: Started Service for using pirate audio display in volumio. Jun 06 19:35:05 pallab systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jun 06 19:35:05 pallab systemd[1]: shairport-sync.service: Succeeded. Jun 06 19:35:05 pallab systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jun 06 19:35:05 pallab systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jun 06 19:35:05 pallab go-librespot[1497]: time="2025-06-06T19:35:05+05:30" level=info msg="running go-librespot 0.2.0" Jun 06 19:35:05 pallab sudo[1509]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:05 pallab go-librespot[1497]: time="2025-06-06T19:35:05+05:30" level=debug msg="app state loaded" Jun 06 19:35:05 pallab sudo[1514]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:05 pallab go-librespot[1497]: time="2025-06-06T19:35:05+05:30" level=debug msg="stored credentials not found" Jun 06 19:35:05 pallab go-librespot[1497]: time="2025-06-06T19:35:05+05:30" level=info msg="api server listening on 127.0.0.1:9879" Jun 06 19:35:05 pallab sudo[1517]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:05 pallab volumio[1208]: info: MPD running with PID1409 Jun 06 19:35:05 pallab volumio[1208]: ,establishing connection Jun 06 19:35:05 pallab sudo[1534]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh Jun 06 19:35:05 pallab sudo[1534]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 06 19:35:05 pallab volumio[1208]: error: MPD error: The expression evaluated to a falsy value: Jun 06 19:35:05 pallab volumio[1208]: assert.ok(self.idling) Jun 06 19:35:05 pallab volumio[1208]: error: The expression evaluated to a falsy value: Jun 06 19:35:05 pallab volumio[1208]: assert.ok(self.idling) Jun 06 19:35:05 pallab volumio[1208]: error: MPD error: The expression evaluated to a falsy value: Jun 06 19:35:05 pallab volumio[1208]: assert.ok(self.idling) Jun 06 19:35:05 pallab volumio[1208]: error: The expression evaluated to a falsy value: Jun 06 19:35:05 pallab volumio[1208]: assert.ok(self.idling) Jun 06 19:35:05 pallab volumio[1208]: info: Shairport-Sync Started Jun 06 19:35:05 pallab volumio[1208]: Error adding Membership: Error: addMembership EINVAL Jun 06 19:35:05 pallab volumio[1208]: info: Shairport-Sync Started Jun 06 19:35:05 pallab volumio[1208]: info: Shairport-Sync Started Jun 06 19:35:05 pallab volumio[1208]: error: updateQueue error: null Jun 06 19:35:05 pallab volumio[1516]: cset: --> shielding system active with Jun 06 19:35:05 pallab volumio[1516]: cset: "system" cpuset of CPUSPEC(1-3) with 114 tasks running Jun 06 19:35:05 pallab volumio[1516]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Jun 06 19:35:05 pallab systemd[1]: Started Shield Volumio Music Services in the User CPU Set. Jun 06 19:35:05 pallab systemd[1]: Reloading. Jun 06 19:35:05 pallab volumio[1521]: Traceback (most recent call last): Jun 06 19:35:05 pallab volumio[1521]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 13, in Jun 06 19:35:05 pallab volumio[1521]: import ST7789 # v0.0.6 Jun 06 19:35:05 pallab volumio[1521]: ModuleNotFoundError: No module named 'ST7789' Jun 06 19:35:05 pallab go-librespot[1497]: time="2025-06-06T19:35:05+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 06 19:35:05 pallab go-librespot[1497]: time="2025-06-06T19:35:05+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 06 19:35:05 pallab go-librespot[1497]: time="2025-06-06T19:35:05+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 06 19:35:05 pallab go-librespot[1497]: time="2025-06-06T19:35:05+05:30" level=info msg="zeroconf server listening on port 40865" Jun 06 19:35:06 pallab systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Jun 06 19:35:06 pallab systemd[1]: getty@tty1.service: Current command vanished from the unit file, execution of the command list won't be resumed. Jun 06 19:35:06 pallab systemd[1]: pirateaudio.service: Main process exited, code=exited, status=1/FAILURE Jun 06 19:35:06 pallab systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Jun 06 19:35:06 pallab sudo[1534]: pam_unix(sudo:session): session closed for user root Jun 06 19:35:06 pallab volumio[1208]: info: succeeded Jun 06 19:35:06 pallab systemd[1]: pirateaudio.service: Service RestartSec=100ms expired, scheduling restart. Jun 06 19:35:06 pallab systemd[1]: pirateaudio.service: Scheduled restart job, restart counter is at 2. Jun 06 19:35:06 pallab systemd[1]: Stopped Service for using pirate audio display in volumio. Jun 06 19:35:06 pallab systemd[1]: Started Service for using pirate audio display in volumio. Jun 06 19:35:06 pallab volumio[1377]: Generating RSA private key, 4096 bit long modulus (2 primes) Jun 06 19:35:07 pallab volumio[1208]: info: [yt-cast-receiver] DIAL server listening on port 8098 Jun 06 19:35:07 pallab volumio[1208]: info: CoreCommandRouter::volumioRetrievevolume Jun 06 19:35:07 pallab volumio[1208]: info: CoreCommandRouter::volumioGetState Jun 06 19:35:07 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:07 pallab volumio[1208]: info: CoreStateMachine::pushState Jun 06 19:35:07 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:07 pallab volumio[1208]: info: CoreCommandRouter::volumioPushState Jun 06 19:35:07 pallab volumio[1561]: Traceback (most recent call last): Jun 06 19:35:07 pallab volumio[1561]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 13, in Jun 06 19:35:07 pallab volumio[1561]: import ST7789 # v0.0.6 Jun 06 19:35:07 pallab volumio[1561]: ModuleNotFoundError: No module named 'ST7789' Jun 06 19:35:07 pallab volumio[1208]: info: Completed starting Core Plugins Jun 06 19:35:07 pallab volumio[1208]: info: ------------------------------------------- Jun 06 19:35:07 pallab volumio[1208]: info: ----- MyVolumio plugins startup ---- Jun 06 19:35:07 pallab volumio[1208]: info: ------------------------------------------- Jun 06 19:35:07 pallab volumio[1208]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 06 19:35:07 pallab systemd[1]: pirateaudio.service: Main process exited, code=exited, status=1/FAILURE Jun 06 19:35:07 pallab systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Jun 06 19:35:07 pallab systemd[1]: pirateaudio.service: Service RestartSec=100ms expired, scheduling restart. Jun 06 19:35:07 pallab systemd[1]: pirateaudio.service: Scheduled restart job, restart counter is at 3. Jun 06 19:35:07 pallab go-librespot[1497]: time="2025-06-06T19:35:07+05:30" level=debug msg="obtained new client token: AABMzEHNM1gLzkObs7cIFixhTmY7Druksfxctx4hKCoNvDeSYEzwY9zgemgcs1D8JHL58B9VzqA1uuKRvI/PsqBBccpZGRVAJYy1l3KVtB5QIdm6lqw+yx5cfCdmzQX3X+suaMm7uRTv/Eb3sMppWghSrqpc7dD+kdmoSxZos1vKd476n+RxA73xVbCtxPTvJHlBnNi6rCj4l3QXKloL15EHBQJGst3D3SJjhmkLXd5wQyd05qmAhvLAwQ==" Jun 06 19:35:07 pallab systemd[1]: Stopped Service for using pirate audio display in volumio. Jun 06 19:35:07 pallab systemd[1]: Started Service for using pirate audio display in volumio. Jun 06 19:35:07 pallab volumio[1208]: info: go-librespot daemon successfully initialized Jun 06 19:35:07 pallab go-librespot[1497]: time="2025-06-06T19:35:07+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="completed keyexchange" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="completed challenge" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=info msg="authenticated AP as wrwo5pfj1kot19nrri0cwpp28" Jun 06 19:35:08 pallab volumio[1583]: Traceback (most recent call last): Jun 06 19:35:08 pallab volumio[1583]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 13, in Jun 06 19:35:08 pallab volumio[1583]: import ST7789 # v0.0.6 Jun 06 19:35:08 pallab volumio[1583]: ModuleNotFoundError: No module named 'ST7789' Jun 06 19:35:08 pallab systemd[1]: pirateaudio.service: Main process exited, code=exited, status=1/FAILURE Jun 06 19:35:08 pallab systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Jun 06 19:35:08 pallab volumio[1377]: ..........++++ Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=info msg="authenticated Login5 as wrwo5pfj1kot19nrri0cwpp28" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=info msg="accepted zeroconf user wrwo5pfj1kot19nrri0cwpp28 from M2004J19C" Jun 06 19:35:08 pallab systemd[1]: pirateaudio.service: Service RestartSec=100ms expired, scheduling restart. Jun 06 19:35:08 pallab systemd[1]: pirateaudio.service: Scheduled restart job, restart counter is at 4. Jun 06 19:35:08 pallab systemd[1]: Stopped Service for using pirate audio display in volumio. Jun 06 19:35:08 pallab systemd[1]: Started Service for using pirate audio display in volumio. Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="dealer connection opened" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=trace msg="starting accesspoint recv loop" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=trace msg="starting dealer recv loop" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=trace msg="received accesspoint ping" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=debug msg="received connection id: MGYxODliNmMtM2IwYS00MDkxLWE4MTEtZWRiNDY3ODgxNDUzK2RlYWxlcit0Y3A6Ly8wYWM5NDgxMC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArRUYzQzRDRkMzOTlEQ0NDMjdERjgwODdCRjc0QzdFNzQ2MTU2QkRGNDcyNjVERjdGMDIxMDVDRDU3NjRDRUMyMQ==" Jun 06 19:35:08 pallab go-librespot[1497]: time="2025-06-06T19:35:08+05:30" level=trace msg="received accesspoint pong ack" Jun 06 19:35:09 pallab go-librespot[1497]: time="2025-06-06T19:35:09+05:30" level=debug msg="put connect state because NEW_DEVICE" Jun 06 19:35:09 pallab volumio[1584]: Traceback (most recent call last): Jun 06 19:35:09 pallab volumio[1584]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 13, in Jun 06 19:35:09 pallab volumio[1584]: import ST7789 # v0.0.6 Jun 06 19:35:09 pallab volumio[1584]: ModuleNotFoundError: No module named 'ST7789' Jun 06 19:35:09 pallab systemd[1]: pirateaudio.service: Main process exited, code=exited, status=1/FAILURE Jun 06 19:35:09 pallab systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Jun 06 19:35:09 pallab go-librespot[1497]: time="2025-06-06T19:35:09+05:30" level=debug msg="handling transfer player command from 1e8a3f6fa037cf5e072ca563f46daf494e791112" Jun 06 19:35:09 pallab systemd[1]: pirateaudio.service: Service RestartSec=100ms expired, scheduling restart. Jun 06 19:35:09 pallab systemd[1]: pirateaudio.service: Scheduled restart job, restart counter is at 5. Jun 06 19:35:09 pallab systemd[1]: Stopped Service for using pirate audio display in volumio. Jun 06 19:35:09 pallab systemd[1]: Started Service for using pirate audio display in volumio. Jun 06 19:35:09 pallab go-librespot[1497]: time="2025-06-06T19:35:09+05:30" level=debug msg="resolved context of track" uri="spotify:playlist:62AExHK6fK4GlGGhOa1tuF" Jun 06 19:35:09 pallab go-librespot[1497]: time="2025-06-06T19:35:09+05:30" level=trace msg="fetched new page 0 with 88 items (list: 88)" uri="spotify:playlist:62AExHK6fK4GlGGhOa1tuF" Jun 06 19:35:09 pallab go-librespot[1497]: time="2025-06-06T19:35:09+05:30" level=debug msg="loading track (paused: true, position: 122496ms)" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=trace msg="emitting websocket event: will_play" Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1361" Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=warning msg="original track has no formats, alternatives have a total of 8" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=debug msg="selected format OGG_VORBIS_320 (31f6e762cdabc753cf92a640c4df2c3165de6db2)" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=debug msg="requested aes key for file 31f6e762cdabc753cf92a640c4df2c3165de6db2, gid: 1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:10 pallab volumio[1586]: Traceback (most recent call last): Jun 06 19:35:10 pallab volumio[1586]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 13, in Jun 06 19:35:10 pallab volumio[1586]: import ST7789 # v0.0.6 Jun 06 19:35:10 pallab volumio[1586]: ModuleNotFoundError: No module named 'ST7789' Jun 06 19:35:10 pallab volumio[1208]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 06 19:35:10 pallab systemd[1]: pirateaudio.service: Main process exited, code=exited, status=1/FAILURE Jun 06 19:35:10 pallab systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1124" Jun 06 19:35:10 pallab systemd[1]: pirateaudio.service: Service RestartSec=100ms expired, scheduling restart. Jun 06 19:35:10 pallab systemd[1]: pirateaudio.service: Scheduled restart job, restart counter is at 6. Jun 06 19:35:10 pallab systemd[1]: Stopped Service for using pirate audio display in volumio. Jun 06 19:35:10 pallab systemd[1]: Started Service for using pirate audio display in volumio. Jun 06 19:35:10 pallab volumio[1208]: info: Initializing connection to go-librespot Websocket Jun 06 19:35:10 pallab go-librespot[1497]: time="2025-06-06T19:35:10+05:30" level=debug msg="new websocket client" Jun 06 19:35:10 pallab volumio[1208]: info: Connection to go-librespot Websocket established Jun 06 19:35:11 pallab volumio[1587]: Traceback (most recent call last): Jun 06 19:35:11 pallab volumio[1587]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 13, in Jun 06 19:35:11 pallab volumio[1587]: import ST7789 # v0.0.6 Jun 06 19:35:11 pallab volumio[1587]: ModuleNotFoundError: No module named 'ST7789' Jun 06 19:35:11 pallab systemd[1]: pirateaudio.service: Main process exited, code=exited, status=1/FAILURE Jun 06 19:35:11 pallab systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Jun 06 19:35:11 pallab systemd[1]: pirateaudio.service: Service RestartSec=100ms expired, scheduling restart. Jun 06 19:35:11 pallab go-librespot[1497]: time="2025-06-06T19:35:11+05:30" level=debug msg="fetched first chunk of 33, total size is 17242220 bytes" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:11 pallab systemd[1]: pirateaudio.service: Scheduled restart job, restart counter is at 7. Jun 06 19:35:11 pallab systemd[1]: Stopped Service for using pirate audio display in volumio. Jun 06 19:35:11 pallab systemd[1]: pirateaudio.service: Start request repeated too quickly. Jun 06 19:35:11 pallab systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Jun 06 19:35:11 pallab systemd[1]: Failed to start Service for using pirate audio display in volumio. Jun 06 19:35:11 pallab go-librespot[1497]: time="2025-06-06T19:35:11+05:30" level=debug msg="fetched chunk 2/32, size: 524288" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:11 pallab go-librespot[1497]: time="2025-06-06T19:35:11+05:30" level=debug msg="fetched chunk 3/32, size: 524288" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:11 pallab go-librespot[1497]: time="2025-06-06T19:35:11+05:30" level=debug msg="fetched chunk 1/32, size: 524288" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="fetched chunk 11/32, size: 524288" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="fetched chunk 9/32, size: 524288" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="fetched chunk 10/32, size: 524288" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="fetched chunk 8/32, size: 524288" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=trace msg="seek to 122496ms (diff: 120ms, samples: 5402073, bytes: 4674006)" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="created new output device" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=info msg="loaded track \"Madari\" (paused: true, position: 122496ms, duration: 463786ms, prefetched: false)" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=trace msg="emitting websocket event: metadata" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=trace msg="emitting websocket event: active" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="sending successful reply for dealer request" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jun 06 19:35:12 pallab volumio[1208]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1ppdJWEPtU0ETfe5fd04rB","name":"Madari","artist_names":["Clinton Cerejo","Vishal Dadlani","Sonu Kakkar"],"album_name":"Best of Coke Studio @ MTV Season, 2","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02902aeb3d8bdf021cff362627","position":122496,"duration":463786,"release_date":"year:2012 month:12 day:7","track_number":3,"disc_number":1}} Jun 06 19:35:12 pallab volumio[1208]: SPOTIFY: received: {"type":"active","data":null} Jun 06 19:35:12 pallab volumio[1208]: info: Aligning Spotify Volume to Volumio Volume Jun 06 19:35:12 pallab volumio[1208]: info: CoreCommandRouter::volumioGetState Jun 06 19:35:12 pallab volumio[1208]: info: CorePlayQueue::getTrack 0 Jun 06 19:35:12 pallab volumio[1208]: info: Setting Spotify Volume from Volumio: 100 Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=trace msg="emitting websocket event: paused" Jun 06 19:35:12 pallab volumio[1208]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:1ppdJWEPtU0ETfe5fd04rB","play_origin":"playlist"}} Jun 06 19:35:12 pallab volumio[1208]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="handling resume player command from 1e8a3f6fa037cf5e072ca563f46daf494e791112" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=trace msg="seek to 122496ms (diff: 120ms, samples: 5402073, bytes: 4674006)" uri="spotify:track:1ppdJWEPtU0ETfe5fd04rB" Jun 06 19:35:12 pallab volumio[1208]: TypeError: Cannot read property 'service' of undefined Jun 06 19:35:12 pallab volumio[1208]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) Jun 06 19:35:12 pallab volumio[1208]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:274:18) Jun 06 19:35:12 pallab volumio[1208]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) Jun 06 19:35:12 pallab volumio[1208]: at WebSocket.emit (events.js:315:20) Jun 06 19:35:12 pallab volumio[1208]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jun 06 19:35:12 pallab volumio[1208]: at Receiver.emit (events.js:315:20) Jun 06 19:35:12 pallab volumio[1208]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jun 06 19:35:12 pallab volumio[1208]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jun 06 19:35:12 pallab volumio[1208]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jun 06 19:35:12 pallab volumio[1208]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jun 06 19:35:12 pallab volumio[1208]: at writeOrBuffer (internal/streams/writable.js:358:12) Jun 06 19:35:12 pallab volumio[1208]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jun 06 19:35:12 pallab volumio[1208]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jun 06 19:35:12 pallab volumio[1208]: at Socket.emit (events.js:315:20) Jun 06 19:35:12 pallab volumio[1208]: at addChunk (internal/streams/readable.js:309:12) Jun 06 19:35:12 pallab volumio[1208]: at readableAddChunk (internal/streams/readable.js:284:9) Jun 06 19:35:12 pallab volumio[1208]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Jun 06 19:35:12 pallab go-librespot[1497]: time="2025-06-06T19:35:12+05:30" level=debug msg="resume track at 122376ms" Jun 06 19:35:13 pallab go-librespot[1497]: time="2025-06-06T19:35:13+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 06 19:35:13 pallab go-librespot[1497]: time="2025-06-06T19:35:13+05:30" level=trace msg="scheduling prefetch in 311s" Jun 06 19:35:13 pallab go-librespot[1497]: time="2025-06-06T19:35:13+05:30" level=debug msg="sending successful reply for dealer request" Jun 06 19:35:13 pallab go-librespot[1497]: time="2025-06-06T19:35:13+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jun 06 19:35:13 pallab go-librespot[1497]: time="2025-06-06T19:35:13+05:30" level=trace msg="emitting websocket event: playing" Jun 06 19:35:13 pallab sudo[1597]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-06 19:34 Jun 06 19:35:13 pallab sudo[1597]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"