-- Logs begin at Thu 2019-02-14 19:11:58 JST, end at Tue 2024-05-07 19:38:51 JST. -- May 07 19:38:47 rivo ntpd[5704]: receive: Unexpected origin timestamp 0xe9db1f0f.56cbdadd does not match aorg 0000000000.00000000 from server@45.77.20.103 xmt 0xe9e48337.47dbcca4 May 07 19:38:47 rivo ntpd[5704]: receive: Unexpected origin timestamp 0xe9db1f0f.56d9e2e3 does not match aorg 0000000000.00000000 from server@122.215.240.51 xmt 0xe9e48337.47e2385e May 07 19:38:47 rivo systemd[1]: Starting Daily apt download activities... May 07 19:38:47 rivo systemd[1]: Starting Daily man-db regeneration... May 07 19:38:47 rivo systemd[1]: man-db.service: Succeeded. May 07 19:38:47 rivo systemd[1]: Started Daily man-db regeneration. May 07 19:38:47 rivo volumio[5289]: info: Initializing connection to go-librespot Websocket May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=debug msg="new websocket client" May 07 19:38:47 rivo volumio[5289]: info: Connection to go-librespot Websocket established May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=debug msg="handling transfer player command from 644757dfe02f97b27afe103c38bb68adf2c163d4" May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=trace msg="fetched new page 0 with 182 items (list: 182)" May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=debug msg="loading track spotify:track:10PX8hD25FmlXu1ddMTmX1 (paused: false, position: 211996ms)" May 07 19:38:47 rivo volumio[5289]: info: Discovery: A device disappeared from network May 07 19:38:47 rivo volumio[5289]: info: Discovery: Device rivo disappeared from network May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=trace msg="emitting websocket event: will_play" May 07 19:38:47 rivo volumio[5289]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:10PX8hD25FmlXu1ddMTmX1","play_origin":"playlist"}} May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1506" May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:10PX8hD25FmlXu1ddMTmX1" May 07 19:38:47 rivo go-librespot[5954]: time="2024-05-07T19:38:47+09:00" level=debug msg="requested aes key for file 66aa08f7443c916233210d48d95e2ff25e72f80c, gid: 10PX8hD25FmlXu1ddMTmX1" May 07 19:38:48 rivo volumio[5289]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 07 19:38:48 rivo volumio[5289]: info: Discovery: adding cec146ba-79f6-47a9-82ca-17ee91f564dd May 07 19:38:48 rivo volumio[5289]: info: Discovery: Found device Rivo May 07 19:38:48 rivo volumio[5289]: info: CoreCommandRouter::volumioGetState May 07 19:38:48 rivo volumio[5289]: info: CorePlayQueue::getTrack 0 May 07 19:38:48 rivo systemd[1]: apt-daily.service: Succeeded. May 07 19:38:48 rivo systemd[1]: Started Daily apt download activities. May 07 19:38:48 rivo systemd[1]: Starting Daily apt upgrade and clean activities... May 07 19:38:49 rivo systemd[1]: apt-daily-upgrade.service: Succeeded. May 07 19:38:49 rivo systemd[1]: Started Daily apt upgrade and clean activities. May 07 19:38:49 rivo go-librespot[5954]: time="2024-05-07T19:38:49+09:00" level=debug msg="fetched first chunk of 17, total size is 8465960 bytes" May 07 19:38:49 rivo go-librespot[5954]: time="2024-05-07T19:38:49+09:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" May 07 19:38:49 rivo go-librespot[5954]: time="2024-05-07T19:38:49+09:00" level=debug msg="fetched chunk 1/16, size: 524288" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="fetched chunk 3/16, size: 524288" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="fetched chunk 2/16, size: 524288" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="fetched chunk 14/16, size: 524288" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=trace msg="seek to 211996ms (diff: 143ms, samples: 9349023, bytes: 7758749)" May 07 19:38:50 rivo kernel: aml_spdif_open May 07 19:38:50 rivo kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:spdif@0 May 07 19:38:50 rivo kernel: set normal 512 fs /4 fs May 07 19:38:50 rivo kernel: set spdifout clk:5644800, mpll:22579200 May 07 19:38:50 rivo kernel: get spdifout clk:5644797, mpll:22579186 May 07 19:38:50 rivo kernel: aml_dai_set_spdif_fmt , fmt 0x4000 May 07 19:38:50 rivo kernel: set normal 512 fs /4 fs May 07 19:38:50 rivo kernel: set spdifout clk:5644800, mpll:22579200 May 07 19:38:50 rivo kernel: get spdifout clk:5644797, mpll:22579186 May 07 19:38:50 rivo kernel: spdif_info: rate: 44100, channel status ch0_l:0x100, ch0_r:0x100, ch1_l:0x0, ch1_r:0x0 May 07 19:38:50 rivo kernel: aml_spdif_fifo_ctrl, bit depth:24, frddr type:4, toddr:type:4 May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=info msg="loaded track \"Hindsight\" (uri: spotify:track:10PX8hD25FmlXu1ddMTmX1, paused: false, position: 211996ms, duration: 231250ms)" May 07 19:38:50 rivo kernel: asoc-aml-card auge_sound: S/PDIF Playback enable May 07 19:38:50 rivo volumio[5289]: info: Checking for updated MCU Firmware May 07 19:38:50 rivo volumio[5289]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 07 19:38:50 rivo volumio[5289]: info: Firware on device is on latest version, no need to update May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=trace msg="emitting websocket event: metadata" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=trace msg="emitting websocket event: active" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="sending successful reply for delaer request" May 07 19:38:50 rivo volumio[5289]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:10PX8hD25FmlXu1ddMTmX1","name":"Hindsight","artist_names":["Robert Gafforelli"],"album_name":"Hindsight","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0281439e56f3d125a1e4fa804e","position":211996,"duration":231250,"release_date":"year:2022 month:8 day:19","track_number":1,"disc_number":1}} May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 07 19:38:50 rivo volumio[5289]: SPOTIFY: received: {"type":"active","data":null} May 07 19:38:50 rivo volumio[5289]: info: Aligning Spotify Volume to Volumio Volume May 07 19:38:50 rivo volumio[5289]: info: CoreCommandRouter::volumioGetState May 07 19:38:50 rivo volumio[5289]: info: CorePlayQueue::getTrack 0 May 07 19:38:50 rivo volumio[5289]: info: Setting Spotify Volume from Volumio: 100 May 07 19:38:50 rivo volumio[5289]: info: Getting Spotify volume May 07 19:38:50 rivo volumio[5289]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 4 May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="fetched chunk 15/16, size: 524288" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 07 19:38:50 rivo go-librespot[5954]: time="2024-05-07T19:38:50+09:00" level=trace msg="emitting websocket event: playing" May 07 19:38:50 rivo volumio[5289]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:10PX8hD25FmlXu1ddMTmX1","play_origin":"playlist"}} May 07 19:38:50 rivo volumio[5289]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 07 19:38:50 rivo volumio[5289]: TypeError: Cannot read property 'service' of undefined May 07 19:38:50 rivo volumio[5289]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) May 07 19:38:50 rivo volumio[5289]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) May 07 19:38:50 rivo volumio[5289]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) May 07 19:38:50 rivo volumio[5289]: at WebSocket.emit (events.js:400:28) May 07 19:38:50 rivo volumio[5289]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) May 07 19:38:50 rivo volumio[5289]: at Receiver.emit (events.js:400:28) May 07 19:38:50 rivo volumio[5289]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 May 07 19:38:50 rivo volumio[5289]: at internal/process/task_queues.js:141:7 May 07 19:38:50 rivo volumio[5289]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) May 07 19:38:50 rivo volumio[5289]: at AsyncResource.runMicrotask (internal/process/task_queues.js:138:8) May 07 19:38:50 rivo volumio[5289]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 07 19:38:51 rivo go-librespot[5954]: time="2024-05-07T19:38:51+09:00" level=debug msg="fetched chunk 16/16, size: 77352" May 07 19:38:51 rivo sudo[6262]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-07 19:37 May 07 19:38:51 rivo sudo[6262]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="e831866afe2db61aee9333a8f5ba9d9fd36609c7" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="rivo" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun 18 Feb 2024 11:41:55 AM CET" VOLUMIO_VERSION="3.629" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Rivo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Rivo" VOLUMIO_HASH="b0437c7088d6645a661a49f6d9fa596a"