-- Logs begin at Tue 2024-09-17 13:28:54 JST, end at Sun 2025-01-19 15:31:11 JST. -- Jan 19 15:31:03 rivo ntpd[3375]: receive: Unexpected origin timestamp 0xea938423.e3fa66f8 does not match aorg 0000000000.00000000 from server@122.215.240.52 xmt 0xeb371aa7.9581f3a9 Jan 19 15:31:03 rivo ntpd[3375]: receive: Unexpected origin timestamp 0xea938423.e406e40a does not match aorg 0000000000.00000000 from server@133.243.238.243 xmt 0xeb371aa7.94cf831a Jan 19 15:31:03 rivo systemd[1]: Starting Daily man-db regeneration... Jan 19 15:31:03 rivo ntpd[3375]: receive: Unexpected origin timestamp 0xea938423.e402dcfc does not match aorg 0000000000.00000000 from server@45.76.221.157 xmt 0xeb371aa7.94e158b2 Jan 19 15:31:03 rivo ntpd[3375]: receive: Unexpected origin timestamp 0xea938423.e41246f2 does not match aorg 0000000000.00000000 from server@202.181.103.212 xmt 0xeb371aa7.94dd98de Jan 19 15:31:03 rivo ntpd[3375]: receive: Unexpected origin timestamp 0xea938423.e41022cb does not match aorg 0000000000.00000000 from server@202.182.111.234 xmt 0xeb371aa7.94f5ac62 Jan 19 15:31:03 rivo ntpd[3375]: receive: Unexpected origin timestamp 0xea938423.e4097eb2 does not match aorg 0000000000.00000000 from server@35.77.84.214 xmt 0xeb371aa7.9501b19e Jan 19 15:31:03 rivo ntpd[3375]: receive: Unexpected origin timestamp 0xea938423.e40bc8b0 does not match aorg 0000000000.00000000 from server@129.250.35.251 xmt 0xeb371aa7.95e74b2e Jan 19 15:31:03 rivo systemd[1]: Starting Daily apt download activities... Jan 19 15:31:03 rivo systemd[1]: man-db.service: Succeeded. Jan 19 15:31:03 rivo systemd[1]: Started Daily man-db regeneration. Jan 19 15:31:03 rivo volumio[3104]: info: Discovery: A device disappeared from network Jan 19 15:31:03 rivo volumio[3104]: info: Discovery: Device rivo disappeared from network Jan 19 15:31:04 rivo ntpd[3375]: Soliciting pool server 118.156.189.22 Jan 19 15:31:04 rivo ntpd[3375]: Soliciting pool server 133.130.121.141 Jan 19 15:31:04 rivo volumio[3104]: info: Discovery: adding f9e97de9-3500-4833-be17-d2ef6605585d Jan 19 15:31:04 rivo volumio[3104]: info: Discovery: Found device Rivo Jan 19 15:31:04 rivo volumio[3104]: info: CoreCommandRouter::volumioGetState Jan 19 15:31:04 rivo volumio[3104]: info: CorePlayQueue::getTrack 0 Jan 19 15:31:04 rivo systemd[1]: apt-daily.service: Succeeded. Jan 19 15:31:04 rivo systemd[1]: Started Daily apt download activities. Jan 19 15:31:04 rivo systemd[1]: Starting Daily apt upgrade and clean activities... Jan 19 15:31:04 rivo volumio[3104]: info: go-librespot daemon successfully initialized Jan 19 15:31:04 rivo systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 19 15:31:04 rivo systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 19 15:31:04 rivo systemd[1]: Stopped go-librespot Daemon. Jan 19 15:31:04 rivo systemd[1]: Started go-librespot Daemon. Jan 19 15:31:04 rivo go-librespot[3594]: Librespot-go daemon starting... Jan 19 15:31:04 rivo go-librespot[3594]: time="2025-01-19T15:31:04+09:00" level=info msg="generated new device id: 66f7120abda843a69916e8718d775ee86a91115a" Jan 19 15:31:05 rivo go-librespot[3594]: time="2025-01-19T15:31:05+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]" Jan 19 15:31:05 rivo go-librespot[3594]: time="2025-01-19T15:31:05+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]" Jan 19 15:31:05 rivo go-librespot[3594]: time="2025-01-19T15:31:05+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]" Jan 19 15:31:05 rivo go-librespot[3594]: time="2025-01-19T15:31:05+09:00" level=debug msg="zeroconf server listening on port 33003" Jan 19 15:31:05 rivo systemd[1]: apt-daily-upgrade.service: Succeeded. Jan 19 15:31:05 rivo systemd[1]: Started Daily apt upgrade and clean activities. Jan 19 15:31:06 rivo systemd[1]: systemd-fsckd.service: Succeeded. Jan 19 15:31:07 rivo go-librespot[3594]: time="2025-01-19T15:31:07+09:00" level=debug msg="obtained new client token: AABp0cq6Cn9fgL2k5vDx1szBo3Zukc3a7jp35nJ9q2+HphDv5/DTkGue6/++j56G61wD2Z+i89whuPnHqlaIGatTctRnbhtS6ImfXV+j1RBRVK7oMcYeceuiSie0r79k8Oh+azYi07G2ayp/uI59z6P6OlyFveMBQVfYhfSPn4nU5Dov5B7ZdzVTDgiMfr5gIpas6eNXYRpq/fNkwQSe4XowkgM8cmeh2IcMenXjDGLyYLUDe9GyO2CKF8asHfI=" Jan 19 15:31:07 rivo volumio[3104]: info: Initializing connection to go-librespot Websocket Jan 19 15:31:07 rivo go-librespot[3594]: time="2025-01-19T15:31:07+09:00" level=debug msg="completed keyexchange" Jan 19 15:31:07 rivo go-librespot[3594]: time="2025-01-19T15:31:07+09:00" level=debug msg="new websocket client" Jan 19 15:31:07 rivo volumio[3104]: info: Connection to go-librespot Websocket established Jan 19 15:31:08 rivo volumio[3104]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="completed challenge" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="authenticated as shin16horii" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="authenticated as shin16horii" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="dealer connection opened" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=info msg="accepted zeroconf user shin16horii from iPhone" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="received connection id: MmE3Y2FiYzktODJiYS00ZmU4LWI3OGEtZDM3NmI3MmRkMjViK2RlYWxlcit0Y3A6Ly8wYWM5NDkzZi5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArQjk3NDhBRkU5QTFBODI0RjNFOEFFQTA4RTkxNTFFMkY0MDE2REI5REFDOEZBMjcwREJEM0E2N0M0OUQ4RUM2Nw==" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="put connect state because NEW_DEVICE" Jan 19 15:31:08 rivo go-librespot[3594]: time="2025-01-19T15:31:08+09:00" level=debug msg="handling transfer player command from 54674e21c4f1fd94feabf6809011a955615efc6a" Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=debug msg="loading track spotify:track:6drwN0HpUC7zJlRCDtD66n (paused: false, position: 21733ms)" Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=trace msg="emitting websocket event: will_play" Jan 19 15:31:09 rivo volumio[3104]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6drwN0HpUC7zJlRCDtD66n","play_origin":"album"}} Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:6drwN0HpUC7zJlRCDtD66n" Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=debug msg="requested aes key for file 75574739e785e656104d0270b0d9378613d6c68d, gid: 6drwN0HpUC7zJlRCDtD66n" Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1341" Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1113" Jan 19 15:31:09 rivo go-librespot[3594]: time="2025-01-19T15:31:09+09:00" level=debug msg="fetched first chunk of 17, total size is 8714752 bytes" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="fetched chunk 1/16, size: 524288" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=trace msg="seek to 21733ms (diff: 94ms, samples: 958425, bytes: 784065)" Jan 19 15:31:10 rivo volumio[3104]: info: Checking for updated MCU Firmware Jan 19 15:31:10 rivo volumio[3104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 19 15:31:10 rivo volumio[3104]: info: Firware on device is on latest version, no need to update Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="fetched chunk 3/16, size: 524288" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=info msg="loaded track \"時の流れに身をまかせ\" (uri: spotify:track:6drwN0HpUC7zJlRCDtD66n, paused: false, position: 21733ms, duration: 237120ms)" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="fetched chunk 2/16, size: 524288" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="fetched chunk 4/16, size: 524288" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=trace msg="emitting websocket event: metadata" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=trace msg="emitting websocket event: active" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="sending successful reply for delaer request" Jan 19 15:31:10 rivo volumio[3104]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6drwN0HpUC7zJlRCDtD66n","name":"時の流れに身をまかせ","artist_names":["Hideaki Tokunaga"],"album_name":"VOCALIST 4","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027cf392f273e7b9a8cfc37621","position":21733,"duration":237120}} Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jan 19 15:31:10 rivo volumio[3104]: SPOTIFY: received: {"type":"active","data":null} Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jan 19 15:31:10 rivo volumio[3104]: info: Aligning Spotify Volume to Volumio Volume Jan 19 15:31:10 rivo volumio[3104]: info: CoreCommandRouter::volumioGetState Jan 19 15:31:10 rivo volumio[3104]: info: CorePlayQueue::getTrack 0 Jan 19 15:31:10 rivo volumio[3104]: info: Setting Spotify Volume from Volumio: 100 Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 19 15:31:10 rivo go-librespot[3594]: time="2025-01-19T15:31:10+09:00" level=trace msg="emitting websocket event: playing" Jan 19 15:31:10 rivo volumio[3104]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6drwN0HpUC7zJlRCDtD66n","play_origin":"album"}} Jan 19 15:31:10 rivo volumio[3104]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 19 15:31:10 rivo volumio[3104]: TypeError: Cannot read property 'service' of undefined Jan 19 15:31:10 rivo volumio[3104]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:322:50) Jan 19 15:31:10 rivo volumio[3104]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:248:18) Jan 19 15:31:10 rivo volumio[3104]: at WebSocket.message (/data/plugins/music_service/spop/index.js:175:14) Jan 19 15:31:10 rivo volumio[3104]: at WebSocket.emit (events.js:400:28) Jan 19 15:31:10 rivo volumio[3104]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1192:20) Jan 19 15:31:10 rivo volumio[3104]: at Receiver.emit (events.js:400:28) Jan 19 15:31:10 rivo volumio[3104]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:560:14) Jan 19 15:31:10 rivo volumio[3104]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:478:17) Jan 19 15:31:10 rivo volumio[3104]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:22) Jan 19 15:31:10 rivo volumio[3104]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:180:18 Jan 19 15:31:10 rivo volumio[3104]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 19 15:31:11 rivo sudo[3653]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-19 15:30 Jan 19 15:31:11 rivo sudo[3653]: 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"