-- Logs begin at Tue 2024-09-17 13:28:54 JST, end at Thu 2024-10-17 15:44:24 JST. -- Oct 17 15:44:15 rivo ntpd[3372]: receive: Unexpected origin timestamp 0xea938421.c3cbcddb does not match aorg 0000000000.00000000 from server@122.215.240.51 xmt 0xeabb30bf.be9df47a Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo systemd[1]: Starting Daily apt download activities... Oct 17 15:44:15 rivo systemd[1]: Starting Daily man-db regeneration... Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 17 15:44:15 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 17 15:44:15 rivo volumio[3100]: error: Serial API: Failed to decode command: MAXVOL, message: 100 Oct 17 15:44:15 rivo volumio[3100]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 17 15:44:15 rivo systemd[1]: man-db.service: Succeeded. Oct 17 15:44:15 rivo systemd[1]: Started Daily man-db regeneration. Oct 17 15:44:16 rivo volumio[3100]: info: VolumeController:: Volume=100 Mute =false Oct 17 15:44:16 rivo volumio[3100]: info: CoreStateMachine::pushState Oct 17 15:44:16 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::volumioPushState Oct 17 15:44:16 rivo sudo[3525]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms 0 0 0 Oct 17 15:44:16 rivo sudo[3525]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 15:44:16 rivo sudo[3525]: pam_unix(sudo:session): session closed for user root Oct 17 15:44:16 rivo volumio[3100]: info: VolumeController:: Volume=100 Mute =false Oct 17 15:44:16 rivo volumio[3100]: info: CoreStateMachine::pushState Oct 17 15:44:16 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::volumioPushState Oct 17 15:44:16 rivo volumio[3100]: info: Discovery: adding f9e97de9-3500-4833-be17-d2ef6605585d Oct 17 15:44:16 rivo volumio[3100]: info: Discovery: Found device Rivo Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::volumioGetState Oct 17 15:44:16 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:16 rivo volumio[3100]: info: Adding Inputs via Serial API Oct 17 15:44:16 rivo volumio[3100]: info: Discovery: A device disappeared from network Oct 17 15:44:16 rivo volumio[3100]: info: Discovery: Device rivo disappeared from network Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::volumioGetState Oct 17 15:44:16 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::volumioGetState Oct 17 15:44:16 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:16 rivo volumio[3100]: info: CoreStateMachine::pushState Oct 17 15:44:16 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::volumioPushState Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::servicePushState Oct 17 15:44:16 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:16 rivo volumio[3100]: 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} Oct 17 15:44:16 rivo volumio[3100]: verbose: CURRENT POSITION 0 Oct 17 15:44:16 rivo volumio[3100]: info: CoreStateMachine::syncState stateService play Oct 17 15:44:16 rivo volumio[3100]: info: CoreStateMachine::syncState currentStatus stop Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::volumiosetSourceActiveno-source Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 17 15:44:16 rivo volumio[3100]: info: Discovery: adding f9e97de9-3500-4833-be17-d2ef6605585d Oct 17 15:44:16 rivo volumio[3100]: info: Discovery: Found device Rivo Oct 17 15:44:16 rivo volumio[3100]: info: CoreCommandRouter::volumioGetState Oct 17 15:44:16 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:16 rivo volumio[3100]: info: MCU Signalled Playback Inactive Oct 17 15:44:16 rivo systemd[1]: apt-daily.service: Succeeded. Oct 17 15:44:16 rivo systemd[1]: Started Daily apt download activities. Oct 17 15:44:16 rivo systemd[1]: Starting Daily apt upgrade and clean activities... Oct 17 15:44:17 rivo volumio[3100]: info: Turning Off Onboard LEDs Oct 17 15:44:17 rivo sudo[3605]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/sys_led/trigger Oct 17 15:44:17 rivo sudo[3605]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 15:44:17 rivo sudo[3605]: pam_unix(sudo:session): session closed for user root Oct 17 15:44:17 rivo sudo[3610]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/tee /sys/class/leds/red_red/trigger Oct 17 15:44:17 rivo sudo[3610]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 15:44:17 rivo sudo[3610]: pam_unix(sudo:session): session closed for user root Oct 17 15:44:17 rivo volumio[3100]: info: Onboard LEDs initialized Oct 17 15:44:17 rivo mpd[3446]: Oct 17 15:44 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 17 15:44:17 rivo systemd[1]: Started Music Player Daemon. Oct 17 15:44:17 rivo sudo[3404]: pam_unix(sudo:session): session closed for user root Oct 17 15:44:17 rivo sudo[3410]: pam_unix(sudo:session): session closed for user root Oct 17 15:44:17 rivo volumio[3100]: info: Completed starting Core Plugins Oct 17 15:44:17 rivo volumio[3100]: info: ------------------------------------------- Oct 17 15:44:17 rivo volumio[3100]: info: ----- MyVolumio plugins startup ---- Oct 17 15:44:17 rivo volumio[3100]: info: ------------------------------------------- Oct 17 15:44:17 rivo volumio[3100]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 17 15:44:17 rivo volumio[3100]: error: MPD error: The expression evaluated to a falsy value: Oct 17 15:44:17 rivo volumio[3100]: assert.ok(self.idling) Oct 17 15:44:17 rivo volumio[3100]: error: The expression evaluated to a falsy value: Oct 17 15:44:17 rivo volumio[3100]: assert.ok(self.idling) Oct 17 15:44:17 rivo volumio[3100]: info: MPD running with PID3446 Oct 17 15:44:17 rivo volumio[3100]: ,establishing connection Oct 17 15:44:17 rivo volumio[3100]: error: updateQueue error: null Oct 17 15:44:17 rivo volumio[3100]: error: updateQueue error: null Oct 17 15:44:17 rivo systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 17 15:44:17 rivo systemd[1]: Started Daily apt upgrade and clean activities. Oct 17 15:44:18 rivo go-librespot[3493]: time="2024-10-17T15:44:18+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-gew1.spotify.com:80]" Oct 17 15:44:18 rivo go-librespot[3493]: time="2024-10-17T15:44:18+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Oct 17 15:44:18 rivo go-librespot[3493]: time="2024-10-17T15:44:18+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Oct 17 15:44:18 rivo go-librespot[3493]: time="2024-10-17T15:44:18+09:00" level=debug msg="zeroconf server listening on port 34455" Oct 17 15:44:19 rivo volumio[3100]: info: go-librespot daemon successfully initialized Oct 17 15:44:20 rivo go-librespot[3493]: time="2024-10-17T15:44:20+09:00" level=debug msg="obtained new client token: AAD98AwDd0SMWKJM2ZHUA/4eX0IjObpmpznMggOfd71KRQ2cJ0UWCwwrD3o92QLJHSr5G0gKLY308ybC643bTFWKfupfmGKLRLI0A0JrbBcZQg0w2XkCRvi3t2y7ogICtc8o6E8UZxhI45caE71AMuPFXE2ElM8RdWEXq9W/n83ndhy0r3pq3djDHTO4JRAbUklbvvUHfx7HFrQ84047vVUnWZTjaYuBvm//etJorL4K4sd11hU2GaxYwGK8" Oct 17 15:44:20 rivo systemd[1]: systemd-fsckd.service: Succeeded. Oct 17 15:44:21 rivo go-librespot[3493]: time="2024-10-17T15:44:21+09:00" level=debug msg="completed keyexchange" Oct 17 15:44:22 rivo volumio[3100]: info: Initializing connection to go-librespot Websocket Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="new websocket client" Oct 17 15:44:22 rivo volumio[3100]: info: Connection to go-librespot Websocket established Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="completed challenge" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="authenticated as shin16horii" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="authenticated as shin16horii" Oct 17 15:44:22 rivo volumio[3100]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="dealer connection opened" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=info msg="accepted zeroconf user shin16horii from iPhone" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 495" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="received connection id: NDU2Njc0ZmQtOWRlNy00YWQ5LWFlOWQtYjBjNmQ2NjE5NTYwK2RlYWxlcit0Y3A6Ly8wYWM5NDgxZS5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArNTkzNjBEQUIwMzk5MDQzNjJGOEYwQkZFMjg5RDkxRDgxQThBMzAzQTE4OEE2MzNBMDIzRDA5RkM2Njc1RDY1RA==" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="put connect state because NEW_DEVICE" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="handling transfer player command from d6a15878f6cbc20936b45b0b2584f889bc54fd82" Oct 17 15:44:22 rivo go-librespot[3493]: time="2024-10-17T15:44:22+09:00" level=debug msg="loading track spotify:track:3XVBdLihbNbxUwZosxcGuJ (paused: false, position: 8862ms)" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=trace msg="emitting websocket event: will_play" Oct 17 15:44:23 rivo volumio[3100]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3XVBdLihbNbxUwZosxcGuJ","play_origin":"playlist/ondemand"}} Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:3XVBdLihbNbxUwZosxcGuJ" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="requested aes key for file df574c93c5d05e1ffe302493c72b4dd254141cf5, gid: 3XVBdLihbNbxUwZosxcGuJ" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1361" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1133" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="fetched first chunk of 16, total size is 8000644 bytes" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=trace msg="seek to 8862ms (diff: 183ms, samples: 390814, bytes: 316130)" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="fetched chunk 3/15, size: 524288" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="fetched chunk 1/15, size: 524288" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=info msg="loaded track \"If I Ain't Got You\" (uri: spotify:track:3XVBdLihbNbxUwZosxcGuJ, paused: false, position: 8862ms, duration: 228706ms)" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="fetched chunk 2/15, size: 524288" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=trace msg="emitting websocket event: metadata" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=trace msg="emitting websocket event: active" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="sending successful reply for delaer request" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 17 15:44:23 rivo volumio[3100]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3XVBdLihbNbxUwZosxcGuJ","name":"If I Ain't Got You","artist_names":["Alicia Keys"],"album_name":"The Diary Of Alicia Keys","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0256ff19308ebeb48e2ba6094b","position":8862,"duration":228706}} Oct 17 15:44:23 rivo volumio[3100]: SPOTIFY: received: {"type":"active","data":null} Oct 17 15:44:23 rivo volumio[3100]: info: Aligning Spotify Volume to Volumio Volume Oct 17 15:44:23 rivo volumio[3100]: info: CoreCommandRouter::volumioGetState Oct 17 15:44:23 rivo volumio[3100]: info: CorePlayQueue::getTrack 0 Oct 17 15:44:23 rivo volumio[3100]: info: Setting Spotify Volume from Volumio: 100 Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 15:44:23 rivo go-librespot[3493]: time="2024-10-17T15:44:23+09:00" level=trace msg="emitting websocket event: playing" Oct 17 15:44:23 rivo volumio[3100]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3XVBdLihbNbxUwZosxcGuJ","play_origin":"playlist/ondemand"}} Oct 17 15:44:23 rivo volumio[3100]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 15:44:23 rivo volumio[3100]: TypeError: Cannot read property 'service' of undefined Oct 17 15:44:23 rivo volumio[3100]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:322:50) Oct 17 15:44:23 rivo volumio[3100]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:248:18) Oct 17 15:44:23 rivo volumio[3100]: at WebSocket.message (/data/plugins/music_service/spop/index.js:175:14) Oct 17 15:44:23 rivo volumio[3100]: at WebSocket.emit (events.js:400:28) Oct 17 15:44:23 rivo volumio[3100]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1192:20) Oct 17 15:44:23 rivo volumio[3100]: at Receiver.emit (events.js:400:28) Oct 17 15:44:23 rivo volumio[3100]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:560:14) Oct 17 15:44:23 rivo volumio[3100]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:478:17) Oct 17 15:44:23 rivo volumio[3100]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:22) Oct 17 15:44:23 rivo volumio[3100]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:180:18 Oct 17 15:44:23 rivo volumio[3100]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 15:44:24 rivo sudo[3644]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-17 15:43 Oct 17 15:44:24 rivo sudo[3644]: 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 05:06:46 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="420eec03f218d056e8306370042003fc"