-- Logs begin at Sat 2024-11-09 02:24:00 JST, end at Fri 2025-01-17 15:19:12 JST. -- Jan 17 15:18:51 rivoplus systemd-timedated[3380]: Changed local time to Fri Jan 17 15:18:51 2025 Jan 17 15:18:51 rivoplus sudo[3378]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:51 rivoplus volumio-time-update[2825]: volumio-time-update-util: System time updated successfully. Jan 17 15:18:51 rivoplus systemd[1]: Started Volumio Time Update Utility. Jan 17 15:18:51 rivoplus volumio[3118]: info: Applying required configuration parameters for plugin hi_res_audio Jan 17 15:18:51 rivoplus volumio[3118]: info: Loading plugin "inputs"... Jan 17 15:18:51 rivoplus systemd[1]: Starting Daily man-db regeneration... Jan 17 15:18:51 rivoplus systemd[1]: Reached target Multi-User System. Jan 17 15:18:51 rivoplus systemd[1]: Reached target Graphical Interface. Jan 17 15:18:51 rivoplus systemd[1]: Starting Update UTMP about System Runlevel Changes... Jan 17 15:18:51 rivoplus systemd[1]: Starting Daily apt download activities... Jan 17 15:18:51 rivoplus systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jan 17 15:18:51 rivoplus systemd[1]: Started Update UTMP about System Runlevel Changes. Jan 17 15:18:51 rivoplus systemd[1]: man-db.service: Succeeded. Jan 17 15:18:51 rivoplus systemd[1]: Started Daily man-db regeneration. Jan 17 15:18:52 rivoplus volumio[3118]: info: Loading plugin "qobuz"... Jan 17 15:18:52 rivoplus systemd[1]: apt-daily.service: Succeeded. Jan 17 15:18:52 rivoplus systemd[1]: Started Daily apt download activities. Jan 17 15:18:52 rivoplus systemd[1]: Starting Daily apt upgrade and clean activities... Jan 17 15:18:53 rivoplus systemd[1]: apt-daily-upgrade.service: Succeeded. Jan 17 15:18:53 rivoplus systemd[1]: Started Daily apt upgrade and clean activities. Jan 17 15:18:53 rivoplus systemd[1]: Startup finished in 13.003s (kernel) + 22.587s (userspace) = 35.591s. Jan 17 15:18:53 rivoplus volumio-remote-updater[2856]: [2025-01-17 15:18:53] [connect] Successful connection Jan 17 15:18:54 rivoplus volumio[3118]: info: Plugin smart_inputs is not enabled Jan 17 15:18:54 rivoplus volumio[3118]: info: Loading plugin "tidal"... Jan 17 15:18:54 rivoplus ntpd[3292]: Soliciting pool server 133.130.121.141 Jan 17 15:18:54 rivoplus ntpd[3292]: Soliciting pool server 45.77.20.103 Jan 17 15:18:54 rivoplus ntpd[3292]: Soliciting pool server 163.44.97.196 Jan 17 15:18:54 rivoplus ntpd[3292]: Soliciting pool server 129.250.35.251 Jan 17 15:18:54 rivoplus ntpd[3292]: Soliciting pool server 133.243.238.163 Jan 17 15:18:54 rivoplus ntpd[3292]: Soliciting pool server 45.76.221.157 Jan 17 15:18:54 rivoplus ntpd[3292]: Soliciting pool server 162.159.200.123 Jan 17 15:18:54 rivoplus ntpd[3292]: Soliciting pool server 162.159.200.123 Jan 17 15:18:55 rivoplus volumio[3118]: info: Loading plugin "rivopluscontrol"... Jan 17 15:18:55 rivoplus ntpd[3292]: Soliciting pool server 122.215.240.51 Jan 17 15:18:55 rivoplus ntpd[3292]: Soliciting pool server 133.243.238.243 Jan 17 15:18:56 rivoplus volumio[3118]: info: Adding this device properties Jan 17 15:18:56 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , setThisDeviceVolumioProperties Jan 17 15:18:56 rivoplus volumio[3118]: info: Setting Additional Device Volumio Properties: [object Object] Jan 17 15:18:56 rivoplus volumio[3118]: info: Loading plugin "updater_comm"... Jan 17 15:18:56 rivoplus volumio[3118]: info: Loading plugin "cec_controller"... Jan 17 15:18:56 rivoplus ntpd[3292]: Soliciting pool server 162.159.200.1 Jan 17 15:18:56 rivoplus volumio[3118]: info: Applying required configuration parameters for plugin cec_controller Jan 17 15:18:56 rivoplus volumio[3118]: info: Plugin mpdemulation is not enabled Jan 17 15:18:56 rivoplus volumio[3118]: info: Loading plugin "rest_api"... Jan 17 15:18:56 rivoplus volumio[3118]: info: Loading plugin "websocket"... Jan 17 15:18:56 rivoplus volumio[3118]: info: Starting Socket.io Server version 2.3.0 Jan 17 15:18:56 rivoplus volumio[3118]: info: Loading i18n strings for locale ja Jan 17 15:18:57 rivoplus volumio[3118]: Updating browse sources language Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::initPlayerControls Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: Express server listening on port 3000 Jan 17 15:18:57 rivoplus volumio[3118]: [Metrics] WebUI: 17s 975.91ms Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreStateMachine::resetVolumioState Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreStateMachine::getcurrentVolume Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::volumioRetrievevolume Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreStateMachine::pushState Jan 17 15:18:57 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::volumioPushState Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 17 15:18:57 rivoplus volumio[3118]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Jan 17 15:18:57 rivoplus volumio[3118]: info: Completed loading Core Plugins Jan 17 15:18:57 rivoplus volumio[3118]: info: Preparing to generate the ALSA configuration file Jan 17 15:18:57 rivoplus volumio[3118]: info: Cannot read play queue from file Jan 17 15:18:57 rivoplus volumio[3118]: info: Volumio Network Manager: Network status updated: 0 Jan 17 15:18:57 rivoplus volumio[3118]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Revision Jan 17 15:18:57 rivoplus volumio[3118]: verbose: New Socket.io Connection to 192.168.68.73 from 192.168.68.52 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Jan 17 15:18:57 rivoplus volumio[3118]: verbose: New Socket.io Connection to 192.168.68.73 from 192.168.68.52 UA: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Jan 17 15:18:57 rivoplus volumio-remote-updater[2856]: [2025-01-17 15:18:57] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1737094733 101 Jan 17 15:18:57 rivoplus volumio[3118]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 Jan 17 15:18:57 rivoplus volumio[3118]: info: Asound.conf file unchanged, so no further update is needed Jan 17 15:18:57 rivoplus volumio[3118]: info: Output device has changed, restarting MPD Jan 17 15:18:57 rivoplus sudo[3536]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 17 15:18:57 rivoplus sudo[3536]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:57 rivoplus volumio[3118]: info: ___________ START PLUGINS ___________ Jan 17 15:18:57 rivoplus sudo[3536]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:57 rivoplus volumio[3118]: info: ControllerMpd::onStart: Initializing MPD Jan 17 15:18:57 rivoplus volumio[3118]: info: Creating MPD Configuration file Jan 17 15:18:57 rivoplus sudo[3538]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 17 15:18:57 rivoplus sudo[3538]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:57 rivoplus systemd[1]: Stopping Music Player Daemon... Jan 17 15:18:57 rivoplus sudo[3542]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 17 15:18:57 rivoplus sudo[3542]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:57 rivoplus sudo[3542]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 17 15:18:57 rivoplus volumio[3118]: info: [1737094737897] CoreMusicLibrary::Adding element Last_100 Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 17 15:18:57 rivoplus volumio[3118]: info: Streaming services startup Jan 17 15:18:57 rivoplus volumio[3118]: info: Starting Streaming Daemon Jan 17 15:18:57 rivoplus sudo[3546]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 17 15:18:57 rivoplus sudo[3546]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:57 rivoplus sudo[3549]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 17 15:18:57 rivoplus sudo[3549]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:57 rivoplus sudo[3549]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:57 rivoplus volumio[3118]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 17 15:18:58 rivoplus volumio[3118]: info: [1737094737998] CoreMusicLibrary::Adding element Webradio Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 17 15:18:58 rivoplus systemd[1]: mpd.service: Succeeded. Jan 17 15:18:58 rivoplus systemd[1]: Stopped Music Player Daemon. Jan 17 15:18:58 rivoplus volumio[3118]: info: Initializing BBC Radios Jan 17 15:18:58 rivoplus systemd[1]: Starting Music Player Daemon... Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 17 15:18:58 rivoplus volumio[3118]: info: Creating Spotify config file Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:58 rivoplus volumio[3118]: error: Hi Res Audio Failed Login: Missing Login Data Jan 17 15:18:58 rivoplus volumio[3118]: info: Adding HIGHRESAUDIO REST API Endpoints Jan 17 15:18:58 rivoplus volumio[3118]: info: Adding getStreamUrlhi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Jan 17 15:18:58 rivoplus volumio[3118]: info: Initializing Serial Communication on port /dev/ttyS3 Jan 17 15:18:58 rivoplus kernel: meson_uart ffd22000.serial: ttyS3 use xtal(24M) 24000000 change 0 to 9600 Jan 17 15:18:58 rivoplus kernel: meson_uart ffd22000.serial: ttyS3 use xtal(24M) 24000000 change 9600 to 9600 Jan 17 15:18:58 rivoplus kernel: meson_uart ffd22000.serial: ttyS3 use xtal(24M) 24000000 change 9600 to 115200 Jan 17 15:18:58 rivoplus volumio[3118]: info: Touch Event Listener Process Starting Jan 17 15:18:58 rivoplus sudo[3556]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 17 15:18:58 rivoplus sudo[3556]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:58 rivoplus sudo[3575]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xinput --test-xi2 --root Jan 17 15:18:58 rivoplus sudo[3575]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:58 rivoplus sudo[3556]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:58 rivoplus sudo[3575]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:58 rivoplus sudo[3586]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -f -y 4 0x18 0x25 0x0 Jan 17 15:18:58 rivoplus sudo[3586]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:58 rivoplus sudo[3586]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:58 rivoplus sudo[3589]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -f -y 4 0x18 0x28 0x0 Jan 17 15:18:58 rivoplus sudo[3589]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:58 rivoplus sudo[3589]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:58 rivoplus sudo[3592]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -f -y 4 0x18 0x29 0x1 Jan 17 15:18:58 rivoplus sudo[3592]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:58 rivoplus sudo[3592]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:58 rivoplus sudo[3595]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/i2cset -f -y 4 0x18 0x33 0x1 Jan 17 15:18:58 rivoplus sudo[3595]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:58 rivoplus sudo[3595]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:58 rivoplus volumio[3118]: info: Apply VIM3L Onboard LEDs Settings Jan 17 15:18:58 rivoplus volumio[3118]: info: Turning On Onboard LEDs Jan 17 15:18:58 rivoplus sudo[3599]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/sys_led/trigger Jan 17 15:18:58 rivoplus sudo[3599]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:58 rivoplus volumio[3118]: info: Starting CEC Event listener Jan 17 15:18:58 rivoplus volumio[3118]: info: Volumio Calling Home Jan 17 15:18:58 rivoplus sudo[3599]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:58 rivoplus sudo[3603]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/red_red/trigger Jan 17 15:18:58 rivoplus sudo[3603]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:58 rivoplus sudo[3603]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:58 rivoplus volumio[3118]: info: Stopping AccessToken refresher cron for QOBUZ Jan 17 15:18:58 rivoplus volumio[3118]: info: AccessToken refresher cron started for QOBUZ Jan 17 15:18:58 rivoplus volumio[3118]: info: Stopping AccessToken refresher cron Jan 17 15:18:58 rivoplus volumio[3118]: info: AccessToken refresher cron started Jan 17 15:18:58 rivoplus volumio[3118]: info: Adding TIDAL REST API Endpoints Jan 17 15:18:58 rivoplus volumio[3118]: info: Adding getStreamUrltidal REST Endpoint for plugin: music_service/tidal Jan 17 15:18:58 rivoplus volumio[3118]: info: Adding QOBUZ REST API Endpoints Jan 17 15:18:58 rivoplus volumio[3118]: info: Adding getStreamUrlqobuz REST Endpoint for plugin: music_service/qobuz Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreStateMachine::setRepeat null single undefined Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreStateMachine::pushState Jan 17 15:18:58 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::volumioPushState Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreStateMachine::setRandom null Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreStateMachine::pushState Jan 17 15:18:58 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::volumioPushState Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 17 15:18:58 rivoplus volumio[3118]: info: Serial port opened successfully Jan 17 15:18:58 rivoplus volumio[3118]: info: Sending serial start messages Jan 17 15:18:58 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:58 rivoplus volumio[3118]: info: Reporting MCU Network Status: 0 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::volumioGetState Jan 17 15:18:59 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::volumioGetVisibleSources Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 17 15:18:59 rivoplus volumio[3118]: info: Touch Event Listener Process Closed Jan 17 15:18:59 rivoplus volumio[3118]: error: Cannot start Volumio Streaming Daemon Jan 17 15:18:59 rivoplus volumio[3118]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 17 15:18:59 rivoplus volumio[3118]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 17 15:18:59 rivoplus volumio[3118]: info: MPD Permissions set Jan 17 15:18:59 rivoplus volumio[3118]: info: MPD Permissions set Jan 17 15:18:59 rivoplus volumio[3118]: info: Spotify config file written Jan 17 15:18:59 rivoplus volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jan 17 15:18:59 rivoplus sudo[3612]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 17 15:18:59 rivoplus sudo[3612]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus systemd[1]: Started go-librespot Daemon. Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Jan 17 15:18:59 rivoplus sudo[3612]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:59 rivoplus go-librespot[3618]: Librespot-go daemon starting... Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Jan 17 15:18:59 rivoplus go-librespot[3618]: time="2025-01-17T15:18:59+09:00" level=info msg="generated new device id: 16a727ba5c6a7c1a42c5393951fcc025a2428622" Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: Discovery: adding ac9e7549-21a6-44a0-8cfe-0901bfc7d71a Jan 17 15:18:59 rivoplus volumio[3118]: info: Discovery: Found device Rivoplus Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::volumioGetState Jan 17 15:18:59 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:18:59 rivoplus volumio[3118]: info: No need to fix Spotify hosts Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setDeviceVolumeOverride Jan 17 15:18:59 rivoplus volumio[3118]: info: Setting Device Volume Override Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::volumioUpdateVolumeSettings Jan 17 15:18:59 rivoplus volumio[3118]: info: Updating Volume Controller Parameters: Device: 5 Name: SMSL USB AUDIO Mixer: Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Jan 17 15:18:59 rivoplus volumio[3118]: info: Disabling external Volume Control Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreStateMachine::pushState Jan 17 15:18:59 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::volumioPushState Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , setAdditionalSVInfo Jan 17 15:18:59 rivoplus volumio[3118]: info: Setting Additional System Software info: Hardware Revision: 1.0 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , setHwFwVersion Jan 17 15:18:59 rivoplus volumio[3118]: info: Setting HW Firmware info: undefined Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , setHwVersion Jan 17 15:18:59 rivoplus volumio[3118]: info: Setting HW Version info: 1.0 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , setAdditionalSVInfo Jan 17 15:18:59 rivoplus volumio[3118]: info: Setting Additional System Software info: Hardware Revision: 1.0, Firmware Version: 0.2.1 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , setHwFwVersion Jan 17 15:18:59 rivoplus volumio[3118]: info: Setting HW Firmware info: 0.2.1 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , setHwVersion Jan 17 15:18:59 rivoplus volumio[3118]: info: Setting HW Version info: 1.0 Jan 17 15:18:59 rivoplus volumio[3118]: info: MCU Signalled PowerOff Capabilities, enabling MCU Poweroff Jan 17 15:18:59 rivoplus volumio[3118]: info: MCU Signalled Headphone Mode Disabled Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: raat , reportHeadphoneState Jan 17 15:18:59 rivoplus volumio[3118]: info: MCU Signalled Sleep Mode Disabled Jan 17 15:18:59 rivoplus volumio[3118]: info: Enabling Advanced system settings configuration Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , addAdditionalUISections Jan 17 15:18:59 rivoplus volumio[3118]: info: Additional UI Settings Added for plugin music_service/inputs Jan 17 15:18:59 rivoplus volumio[3118]: info: MCU Signalled Auto Boot Mode On Power Disabled Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreStateMachine::pushState Jan 17 15:18:59 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 15:18:59 rivoplus volumio[3118]: info: CoreCommandRouter::volumioPushState Jan 17 15:18:59 rivoplus sudo[3641]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms force on Jan 17 15:18:59 rivoplus sudo[3641]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:18:59 rivoplus sudo[3641]: pam_unix(sudo:session): session closed for user root Jan 17 15:18:59 rivoplus volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Jan 17 15:18:59 rivoplus volumio[3118]: info: Volumio called home Jan 17 15:18:59 rivoplus volumio[3118]: error: Serial API: Failed to decode command: MAXVOL, message: 100 Jan 17 15:19:01 rivoplus ntpd[3292]: receive: Unexpected origin timestamp 0xeb3474d3.d6cbbe5b does not match aorg 0000000000.00000000 from server@45.76.211.39 xmt 0xeb3474d5.49bf6531 Jan 17 15:19:01 rivoplus ntpd[3292]: receive: Unexpected origin timestamp 0xeb3474d3.d6bf721f does not match aorg 0000000000.00000000 from server@133.243.238.243 xmt 0xeb3474d5.49a685ee Jan 17 15:19:01 rivoplus ntpd[3292]: receive: Unexpected origin timestamp 0xeb3474d3.d6c6b671 does not match aorg 0000000000.00000000 from server@133.243.238.163 xmt 0xeb3474d5.49aedf8c Jan 17 15:19:01 rivoplus ntpd[3292]: receive: Unexpected origin timestamp 0xeb3474d3.d6d07ca3 does not match aorg 0000000000.00000000 from server@129.250.35.250 xmt 0xeb3474d5.48b4dd8f Jan 17 15:19:01 rivoplus ntpd[3292]: receive: Unexpected origin timestamp 0xeb3474d3.d6c36322 does not match aorg 0000000000.00000000 from server@45.76.221.157 xmt 0xeb3474d5.4997d6d2 Jan 17 15:19:01 rivoplus sudo[3645]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms 0 0 0 Jan 17 15:19:01 rivoplus sudo[3645]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:19:01 rivoplus sudo[3645]: pam_unix(sudo:session): session closed for user root Jan 17 15:19:01 rivoplus volumio[3118]: info: MP1 GPIO: Signalled system ready via GPIO Jan 17 15:19:01 rivoplus volumio[3118]: info: Discovery: A device disappeared from network Jan 17 15:19:01 rivoplus volumio[3118]: info: Discovery: Device rivoplus disappeared from network Jan 17 15:19:01 rivoplus volumio[3118]: info: CoreCommandRouter::volumioGetState Jan 17 15:19:01 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:19:01 rivoplus volumio[3118]: info: Adding Advanced Audio Settings via Serial API Jan 17 15:19:01 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , addAdditionalUISections Jan 17 15:19:01 rivoplus volumio[3118]: info: Additional UI Settings Added for plugin music_service/inputs Jan 17 15:19:01 rivoplus volumio[3118]: info: Adding Inputs via Serial API Jan 17 15:19:01 rivoplus volumio[3118]: info: CoreCommandRouter::volumioGetState Jan 17 15:19:01 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:19:01 rivoplus go-librespot[3618]: time="2025-01-17T15:19:01+09:00" 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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 17 15:19:01 rivoplus go-librespot[3618]: time="2025-01-17T15:19:01+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 17 15:19:01 rivoplus go-librespot[3618]: time="2025-01-17T15:19:01+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 17 15:19:01 rivoplus go-librespot[3618]: time="2025-01-17T15:19:01+09:00" level=debug msg="zeroconf server listening on port 40011" Jan 17 15:19:01 rivoplus volumio[3118]: info: Discovery: adding ac9e7549-21a6-44a0-8cfe-0901bfc7d71a Jan 17 15:19:01 rivoplus volumio[3118]: info: Discovery: Found device Rivoplus Jan 17 15:19:01 rivoplus volumio[3118]: info: CoreCommandRouter::volumioGetState Jan 17 15:19:01 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:19:01 rivoplus mpd[3584]: Jan 17 15:19 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 17 15:19:01 rivoplus systemd[1]: Started Music Player Daemon. Jan 17 15:19:01 rivoplus sudo[3546]: pam_unix(sudo:session): session closed for user root Jan 17 15:19:01 rivoplus sudo[3538]: pam_unix(sudo:session): session closed for user root Jan 17 15:19:01 rivoplus volumio[3118]: info: Completed starting Core Plugins Jan 17 15:19:01 rivoplus volumio[3118]: info: ------------------------------------------- Jan 17 15:19:01 rivoplus volumio[3118]: info: ----- MyVolumio plugins startup ---- Jan 17 15:19:01 rivoplus volumio[3118]: info: ------------------------------------------- Jan 17 15:19:01 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 17 15:19:02 rivoplus volumio[3118]: error: MPD error: The expression evaluated to a falsy value: Jan 17 15:19:02 rivoplus volumio[3118]: assert.ok(self.idling) Jan 17 15:19:02 rivoplus volumio[3118]: error: The expression evaluated to a falsy value: Jan 17 15:19:02 rivoplus volumio[3118]: assert.ok(self.idling) Jan 17 15:19:02 rivoplus volumio[3118]: error: updateQueue error: null Jan 17 15:19:02 rivoplus volumio[3118]: info: MPD running with PID3584 Jan 17 15:19:02 rivoplus volumio[3118]: ,establishing connection Jan 17 15:19:02 rivoplus volumio[3118]: error: updateQueue error: null Jan 17 15:19:02 rivoplus volumio[3118]: info: CoreCommandRouter::servicePushState Jan 17 15:19:02 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:19:02 rivoplus volumio[3118]: verbose: STATE SERVICE {"status":"play","service":"inputs","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"","seek":0,"duration":0,"samplerate":"","bitdepth":"","stream":true,"disableUiControls":true,"channels":2} Jan 17 15:19:02 rivoplus volumio[3118]: verbose: CURRENT POSITION 0 Jan 17 15:19:02 rivoplus volumio[3118]: info: CoreStateMachine::syncState stateService play Jan 17 15:19:02 rivoplus volumio[3118]: info: CoreStateMachine::syncState currentStatus stop Jan 17 15:19:02 rivoplus volumio[3118]: info: CoreCommandRouter::volumiosetSourceActiveno-source Jan 17 15:19:02 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 17 15:19:02 rivoplus volumio[3118]: info: CoreStateMachine::pushState Jan 17 15:19:02 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:19:02 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 15:19:02 rivoplus volumio[3118]: info: CoreCommandRouter::volumioPushState Jan 17 15:19:02 rivoplus volumio[3118]: info: Turning Off Onboard LEDs Jan 17 15:19:02 rivoplus sudo[3661]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/sys_led/trigger Jan 17 15:19:02 rivoplus sudo[3661]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:19:02 rivoplus sudo[3661]: pam_unix(sudo:session): session closed for user root Jan 17 15:19:02 rivoplus sudo[3664]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/red_red/trigger Jan 17 15:19:02 rivoplus sudo[3664]: pam_unix(sudo:session): session opened for user root by (uid=0) Jan 17 15:19:02 rivoplus sudo[3664]: pam_unix(sudo:session): session closed for user root Jan 17 15:19:02 rivoplus volumio[3118]: info: Onboard LEDs initialized Jan 17 15:19:04 rivoplus volumio[3118]: info: go-librespot daemon successfully initialized Jan 17 15:19:05 rivoplus volumio[3118]: info: Reporting MCU Network Status: 1 Jan 17 15:19:05 rivoplus volumio[3118]: info: Volumio Network Manager: Network status updated: 1 Jan 17 15:19:05 rivoplus systemd[1]: systemd-fsckd.service: Succeeded. Jan 17 15:19:06 rivoplus volumio[3118]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 17 15:19:07 rivoplus volumio[3118]: info: Initializing connection to go-librespot Websocket Jan 17 15:19:07 rivoplus go-librespot[3618]: time="2025-01-17T15:19:07+09:00" level=debug msg="new websocket client" Jan 17 15:19:07 rivoplus volumio[3118]: info: Connection to go-librespot Websocket established Jan 17 15:19:07 rivoplus go-librespot[3618]: time="2025-01-17T15:19:07+09:00" level=debug msg="obtained new client token: AACDv+rG5r3zXDb54ug3ma2XyDDJJG+RxJKK0gUHiynp7t+y4vifZeO7c9fCai3lpYiOnaojn/HTDeiXxPXjTD7lWaLz7lAayFqA+8t3kRUvSXQ9/um6RxEYeDjqH4mZNN0fJlve8b4+M2K1dp6OG5hGiV/3+NuLbwWPLZHgZc3uAMWkwWoBoJ4i29dQxXdkEKrg/BPgQ9IEctcDdwOkO8pauzy4LEfL6A+PKrIvyDuO0pW6to8+ANgumQB8JvY=" Jan 17 15:19:07 rivoplus go-librespot[3618]: time="2025-01-17T15:19:07+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Jan 17 15:19:07 rivoplus go-librespot[3618]: time="2025-01-17T15:19:07+09:00" level=debug msg="completed keyexchange" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="completed challenge" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="authenticated as mnc59198j2trig4vuupghx4mt" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="authenticated as mnc59198j2trig4vuupghx4mt" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="dealer connection opened" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=info msg="accepted zeroconf user mnc59198j2trig4vuupghx4mt from iPhone" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="autoplay enabled: false" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="received connection id: MzVkZWI1MDctNzJmNi00ODM3LWI1ZDEtODc2Njk1ODQ4MzdjK2RlYWxlcit0Y3A6Ly8wYWM5NDk0YS5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArRThBQkQxNDNFRkE0N0QxODgzMjEyQ0E1QkE1M0VBOUQ5RjJFNUE3RkFFMkY3OUY2QzM0MDJGMjdFNjI3NTEzQQ==" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="put connect state because NEW_DEVICE" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="handling transfer player command from 26edd8582af78d4183385eb8a15e25c06ae69d79" Jan 17 15:19:08 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DZ06evO1mjssw" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DZ06evO1mjssw" Jan 17 15:19:08 rivoplus go-librespot[3618]: time="2025-01-17T15:19:08+09:00" level=debug msg="loading track (paused: true, position: 140810ms)" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=trace msg="emitting websocket event: will_play" Jan 17 15:19:09 rivoplus volumio[3118]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2eGvxu3yDYylUCDzbSZk41","play_origin":"playlist/ondemand"}} Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="selected format OGG_VORBIS_320 (2267cfb77353fb2a34acb8d018fdd5ac2eba018b)" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="requested aes key for file 2267cfb77353fb2a34acb8d018fdd5ac2eba018b, gid: 2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1361" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1125" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="fetched first chunk of 18, total size is 9164924 bytes" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:09 rivoplus volumio[3118]: info: Checking for updated MCU Firmware Jan 17 15:19:09 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 17 15:19:09 rivoplus volumio[3118]: info: Firware on device is on latest version, no need to update Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=debug msg="fetched chunk 9/17, size: 524288" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:09 rivoplus go-librespot[3618]: time="2025-01-17T15:19:09+09:00" level=trace msg="seek to 140810ms (diff: 151ms, samples: 6209721, bytes: 4960165)" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:10 rivoplus go-librespot[3618]: time="2025-01-17T15:19:10+09:00" level=debug msg="fetched chunk 10/17, size: 524288" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:10 rivoplus go-librespot[3618]: time="2025-01-17T15:19:10+09:00" level=debug msg="fetched chunk 11/17, size: 524288" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:10 rivoplus go-librespot[3618]: time="2025-01-17T15:19:10+09:00" level=debug msg="fetched chunk 12/17, size: 524288" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:10 rivoplus volumio[3118]: info: Getting Spotify volume Jan 17 15:19:10 rivoplus volumio[3118]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 17 15:19:10 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="created new output device" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=info msg="loaded track \"サヨナラCOLOR (feat. 忌野清志郎)\" (paused: true, position: 140810ms, duration: 257026ms, prefetched: false)" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=trace msg="emitting websocket event: metadata" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=trace msg="emitting websocket event: active" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="sending successful reply for dealer request" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=trace msg="emitting websocket event: paused" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=debug msg="handling resume player command from 26edd8582af78d4183385eb8a15e25c06ae69d79" Jan 17 15:19:11 rivoplus go-librespot[3618]: time="2025-01-17T15:19:11+09:00" level=trace msg="seek to 140810ms (diff: 151ms, samples: 6209721, bytes: 4960165)" uri="spotify:track:2eGvxu3yDYylUCDzbSZk41" Jan 17 15:19:11 rivoplus volumio[3118]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 17 15:19:11 rivoplus volumio[3118]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 17 15:19:11 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 17 15:19:11 rivoplus volumio[3118]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 17 15:19:11 rivoplus volumio[3118]: info: Starting MyVolumio Remote Streaming Endpoints Jan 17 15:19:11 rivoplus volumio[3118]: info: MyVolumio login type: Token Jan 17 15:19:11 rivoplus volumio[3118]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 17 15:19:11 rivoplus volumio[3118]: error: [MyVolumio PluginManager] Could not read package.json file: Error: /myvolumio/plugins/music_service/streaming_services//package.json: ENOENT: no such file or directory, open '/myvolumio/plugins/music_service/streaming_services//package.json' Jan 17 15:19:11 rivoplus volumio[3118]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2eGvxu3yDYylUCDzbSZk41","name":"サヨナラCOLOR (feat. 忌野清志郎)","artist_names":["Hanare Gumi","clammbon","ナタリー・ワイズ","Kiyoshiro Imawano"],"album_name":"サヨナラCOLOR (feat. 忌野清志郎)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ff1c3d3fd8e00f0155c52ac1","position":140810,"duration":257026,"release_date":"year:2005 month:8 day:6","track_number":1,"disc_number":1}} Jan 17 15:19:11 rivoplus volumio[3118]: SPOTIFY: received: {"type":"active","data":null} Jan 17 15:19:11 rivoplus volumio[3118]: info: Aligning Spotify Volume to Volumio Volume Jan 17 15:19:11 rivoplus volumio[3118]: info: CoreCommandRouter::volumioGetState Jan 17 15:19:11 rivoplus volumio[3118]: info: CorePlayQueue::getTrack 0 Jan 17 15:19:11 rivoplus volumio[3118]: info: Setting Spotify Volume from Volumio: 100 Jan 17 15:19:11 rivoplus volumio[3118]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:2eGvxu3yDYylUCDzbSZk41","play_origin":"playlist/ondemand"}} Jan 17 15:19:11 rivoplus volumio[3118]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 17 15:19:11 rivoplus volumio[3118]: TypeError: Cannot read property 'service' of undefined Jan 17 15:19:11 rivoplus volumio[3118]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Jan 17 15:19:11 rivoplus volumio[3118]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Jan 17 15:19:11 rivoplus volumio[3118]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Jan 17 15:19:11 rivoplus volumio[3118]: at WebSocket.emit (events.js:400:28) Jan 17 15:19:11 rivoplus volumio[3118]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jan 17 15:19:11 rivoplus volumio[3118]: at Receiver.emit (events.js:400:28) Jan 17 15:19:11 rivoplus volumio[3118]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jan 17 15:19:11 rivoplus volumio[3118]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jan 17 15:19:11 rivoplus volumio[3118]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jan 17 15:19:11 rivoplus volumio[3118]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jan 17 15:19:11 rivoplus volumio[3118]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 17 15:19:12 rivoplus go-librespot[3618]: time="2025-01-17T15:19:12+09:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Jan 17 15:19:12 rivoplus go-librespot[3618]: time="2025-01-17T15:19:12+09:00" level=debug msg="resume track at 140659ms" Jan 17 15:19:12 rivoplus go-librespot[3618]: time="2025-01-17T15:19:12+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 17 15:19:12 rivoplus go-librespot[3618]: time="2025-01-17T15:19:12+09:00" level=trace msg="scheduling prefetch in 86s" Jan 17 15:19:12 rivoplus go-librespot[3618]: time="2025-01-17T15:19:12+09:00" level=debug msg="sending successful reply for dealer request" Jan 17 15:19:12 rivoplus go-librespot[3618]: time="2025-01-17T15:19:12+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 17 15:19:12 rivoplus go-librespot[3618]: time="2025-01-17T15:19:12+09:00" level=trace msg="emitting websocket event: playing" Jan 17 15:19:12 rivoplus sudo[3698]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-17 15:18 Jan 17 15:19:12 rivoplus sudo[3698]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:24:00 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="a9e7f7cddbf07b638557a97b929dd627"