Feb 17 13:11:19 volumio go-librespot[5918]: time="2026-02-17T13:11:19+08:00" level=trace msg="received accesspoint ping" Feb 17 13:11:19 volumio go-librespot[5918]: time="2026-02-17T13:11:19+08:00" level=trace msg="received accesspoint pong ack" Feb 17 13:11:19 volumio go-librespot[5918]: time="2026-02-17T13:11:19+08:00" level=trace msg="sent dealer ping" Feb 17 13:11:19 volumio go-librespot[5918]: time="2026-02-17T13:11:19+08:00" level=trace msg="received dealer pong" Feb 17 13:11:21 volumio volumio[3307]: info: CALLMETHOD: music_service ytmusic configSaveI18n [object Object] Feb 17 13:11:21 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: ytmusic , configSaveI18n Feb 17 13:11:21 volumio volumio[3307]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 17 13:11:37 volumio volumio[3307]: info: CALLMETHOD: music_service ytmusic configSavePlayback [object Object] Feb 17 13:11:37 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: ytmusic , configSavePlayback Feb 17 13:11:39 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:11:39 volumio volumio[3307]: info: CorePlayQueue::getTrack 0 Feb 17 13:11:49 volumio go-librespot[5918]: time="2026-02-17T13:11:49+08:00" level=trace msg="sent dealer ping" Feb 17 13:11:49 volumio go-librespot[5918]: time="2026-02-17T13:11:49+08:00" level=trace msg="received dealer pong" Feb 17 13:11:50 volumio volumio[3307]: info: [yt-cast-receiver] Connecting sender through DIAL... Feb 17 13:11:52 volumio volumio[3307]: info: [yt-cast-receiver] (YouTube) Sender connected: OPPO CPH2357 (user: 碧鶯) Feb 17 13:11:52 volumio volumio[3307]: info: [ytcr] ***** Sender connected ***** Feb 17 13:11:52 volumio volumio[3307]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 17 13:11:58 volumio volumio[3307]: info: [yt-cast-receiver] Player.resume() Feb 17 13:11:58 volumio volumio[3307]: info: [yt-cast-receiver] Player.play(): 9c43wAwFeeA @ 0s Feb 17 13:11:58 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:11:58 volumio volumio[3307]: info: CorePlayQueue::getTrack 0 Feb 17 13:11:58 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:11:58 volumio volumio[3307]: info: CorePlayQueue::getTrack 0 Feb 17 13:11:58 volumio volumio[3307]: info: CoreCommandRouter::volumioStop Feb 17 13:11:58 volumio volumio[3307]: info: CoreStateMachine::stop Feb 17 13:11:58 volumio volumio[3307]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 13:11:59 volumio volumio[3307]: info: [ytcr] Innertube support service: Start service with Deno: deno 2.6.8 (stable, release, x86_64-unknown-linux-gnu) Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:11:59 volumio volumio[3307]: info: CorePlayQueue::getTrack 0 Feb 17 13:11:59 volumio volumio[3307]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:11:59 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:11:59 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:11:59 volumio volumio[3307]: info: FusionDsp - Volumio is not playing Feb 17 13:11:59 volumio volumio[3307]: info: FusionDsp - Clipped samples monitor stopped Feb 17 13:11:59 volumio volumio[3307]: info: FusionDsp - Volumio is not playing Feb 17 13:11:59 volumio volumio[3307]: info: FusionDsp - Clipped samples monitor stopped Feb 17 13:11:59 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 13:11:59 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:11:59 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:11:59 volumio volumio[3307]: info: CorePlayQueue::getTrack 0 Feb 17 13:11:59 volumio volumio[3307]: verbose: STATE SERVICE {"status":"stop","service":"ytcr","albumart":"/albumart","uri":"","trackType":"YouTube","seek":0,"duration":0,"volume":100,"mute":false} Feb 17 13:11:59 volumio volumio[3307]: verbose: CURRENT POSITION 0 Feb 17 13:11:59 volumio volumio[3307]: info: CoreStateMachine::syncState stateService stop Feb 17 13:11:59 volumio volumio[3307]: info: CoreStateMachine::syncState currentStatus pause Feb 17 13:11:59 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 13:11:59 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:11:59 volumio volumio[3307]: info: FusionDsp - Volumio is not playing Feb 17 13:11:59 volumio volumio[3307]: info: FusionDsp - Clipped samples monitor stopped Feb 17 13:11:59 volumio volumio[3307]: info: FusionDsp - Volumio is not playing Feb 17 13:11:59 volumio volumio[3307]: info: FusionDsp - Clipped samples monitor stopped Feb 17 13:11:59 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 13:11:59 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 13:11:59 volumio volumio[3307]: warn: [yt-cast-receiver] DefaultPlaylistRequestHandler failed to mark video 9c43wAwFeeA as watched: Feb 17 13:11:59 volumio volumio[3307]: (Error) No playback tracking URL found Feb 17 13:11:59 volumio volumio[3307]: Error: No playback tracking URL found Feb 17 13:11:59 volumio volumio[3307]: at DefaultPlaylistRequestHandler.markWatched (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/DefaultPlaylistRequestHandler.js:185:19) Feb 17 13:11:59 volumio volumio[3307]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Feb 17 13:11:59 volumio volumio[3307]: at async DefaultPlaylistRequestHandler.getPreviousNextVideos (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/DefaultPlaylistRequestHandler.js:96:9) Feb 17 13:11:59 volumio volumio[3307]: at async DefaultPlaylistRequestHandler.getPreviousNextVideosAbortable (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/PlaylistRequestHandler.js:36:24) Feb 17 13:11:59 volumio volumio[3307]: at async Playlist._Playlist_refreshPreviousNext (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/Playlist.js:314:23) Feb 17 13:11:59 volumio volumio[3307]: at async Playlist.updateByMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/Playlist.js:134:9) Feb 17 13:11:59 volumio volumio[3307]: at async YouTubeApp._YouTubeApp_handleIncomingMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/YouTubeApp.js:403:13) Feb 17 13:11:59 volumio volumio[3307]: at async YouTubeApp._YouTubeApp_handleIncomingMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/app/YouTubeApp.js:302:13) Feb 17 13:12:00 volumio volumio[3307]: info: [yt-cast-receiver] Player.stop() Feb 17 13:12:00 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:00 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:00 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:00 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:00 volumio volumio[3307]: info: [yt-cast-receiver] Player.play(): 9c43wAwFeeA @ 0s Feb 17 13:12:00 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:00 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:00 volumio volumio[3307]: info: FusionDsp - Volumio is not playing Feb 17 13:12:00 volumio volumio[3307]: info: FusionDsp - Clipped samples monitor stopped Feb 17 13:12:00 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 13:12:01 volumio volumio[3307]: info: [yt-cast-receiver] Player.resume() Feb 17 13:12:01 volumio volumio[3307]: info: [yt-cast-receiver] Player.play(): 9c43wAwFeeA @ 0s Feb 17 13:12:01 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:01 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:04 volumio volumio[3307]: info: [ytcr] Innertube support service: result: {"status":"started","server":{"address":"127.0.0.1","port":44217}} Feb 17 13:12:04 volumio volumio[3307]: info: [ytcr] Innertube support service running at http://127.0.0.1:44217 Feb 17 13:12:07 volumio volumio[3307]: info: [ytcr] Obtained session PO token using visitorData (expires in 43199 seconds) Feb 17 13:12:09 volumio volumio[3307]: info: [ytcr] Going to refresh session PO token in 43099 seconds Feb 17 13:12:09 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:09 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:09 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:09 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:09 volumio volumio[3307]: info: FusionDsp - Volumio is not playing Feb 17 13:12:09 volumio volumio[3307]: info: FusionDsp - Clipped samples monitor stopped Feb 17 13:12:09 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 13:12:09 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:09 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:09 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:09 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:09 volumio volumio[3307]: info: FusionDsp - Volumio is not playing Feb 17 13:12:09 volumio volumio[3307]: info: FusionDsp - Clipped samples monitor stopped Feb 17 13:12:09 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 13:12:10 volumio volumio[3307]: info: [ytcr] (9c43wAwFeeA) fetching player data using YTMUSIC client... Feb 17 13:12:10 volumio volumio[3307]: info: [ytcr] (猜不透) validating stream URL "https://rr1---sn-ipoxu-umbr.googlevideo.com/videoplayback?expire=1771326730&ei=qviTacrpGfXm1d8PoIzGyA0&ip=114.38.13.74&id=o-AIeTlKl0zeux5i-oDpM3M4udDJwJrL-jG21WR8-bV25z&itag=251&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&cps=699&met=1771305130%2C&mh=Ec&mm=31%2C29&mn=sn-ipoxu-umbr%2Csn-ojun55-55&ms=au%2Crdu&mv=m&mvi=1&pl=24&rms=au%2Cau&gcr=tw&initcwndbps=3516250&siu=1&bui=AVNa5-xV9mbf_nFTuOCmstQgWT18TvN3mOpqUgxO_m6mJMcsXRficNO_MLbZeKSJHxqzLOZJJw&spc=6dlaFA3zXb3f9ToSyt_dXUKDKZAn6eC3433q5FksDnmhLypJ7A&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=suB0QD2Zcz5siPLKJyp-YMQS&rqh=1&gir=yes&clen=3972211&dur=233.381&lmt=1762107158258051&mt=1771304721&fvip=5&keepalive=yes&fexp=51552689%2C51565116%2C51565681%2C51580968%2C51772949&c=WEB_REMIX&sefc=1&txp=5532534&n=oH20aaBps_UYuA&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cxpc%2Cgcr%2Csiu%2Cbui%2Cspc%2Cvprv%2Csvpuc%2Cmime%2Cns%2Crqh%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=cps%2Cmet%2Cmh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpl%2Crms%2Cinitcwndbps&lsig=APaTxxMwRQIgSOELC2qzpJCcO4ZSwm5Pdo1KDGiAayO7fp3RMpyHIjsCIQD3fWbVarIJZ7VqFdcB774iqHkO7b0c1_9DWvDUj-eLig%3D%3D&sig=AJEij0EwRQIgJyklt2PgqrGaEW2Md5TkrXZpuveAzsFwVuJhk0677lUCIQDwqHkO18_AImedsIzMbY3iwJkopcVadsrqYjfqpkT7Ow%3D%3D&pot=MlWdkpTGd8QWep2sQkXynkv3HUQ7oqF1N0o0Pm7lkBfc63UNK430MlGu7SG5YJq6T7VamdDeGKVhnjHqDGUcnIC1J7-GyIrIIb0y6FiMbtgqI_QqUbez&cver=1.20250219.01.00"... Feb 17 13:12:10 volumio volumio[3307]: info: [ytcr] (猜不透) stream validated in 0.028s. Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:10 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:11 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:11 volumio volumio[3307]: info: Ignoring MPD Status Update Feb 17 13:12:11 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:11 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:11 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:11 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 13:12:11 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:11 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:11 volumio volumio[3307]: warn: FusionDsp - Monitor WebSocket not open, skipping commands Feb 17 13:12:11 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 17 13:12:11 volumio volumio[3307]: info: FusionDsp - Clipping Monitor started Feb 17 13:12:11 volumio volumio[3307]: info: FusionDsp - ---- read samplerate, raw: 48000,S32_LE,2,32 Feb 17 13:12:11 volumio volumio[3307]: info: FusionDsp - ---- read samplerate from file: 48000 Feb 17 13:12:11 volumio volumio[3307]: info: camilladsp stopping service pid 5043... Feb 17 13:12:12 volumio volumio[3307]: grep: /proc/5043/cmdline: binary file matches Feb 17 13:12:12 volumio volumio[3307]: grep: /proc/5043/cmdline: binary file matches Feb 17 13:12:12 volumio volumio[3307]: grep: /proc/5043/cmdline: binary file matches Feb 17 13:12:12 volumio volumio[3307]: grep: /proc/5043/cmdline: binary file matches Feb 17 13:12:12 volumio volumio[3307]: grep: /proc/5043/cmdline: binary file matches Feb 17 13:12:12 volumio volumio[3307]: info: camilladsp service terminated, instance 1 Feb 17 13:12:12 volumio volumio[3307]: info: FusionDsp - If filter freq >samplerate/2 then disable it Feb 17 13:12:12 volumio volumio[3307]: info: camilladsp service started and running in background, instance 1 Feb 17 13:12:12 volumio volumio[3307]: info: FusionDsp - Clipping Monitor reconnecting in 2000ms Feb 17 13:12:12 volumio volumio[3307]: info: camilladsp respawn in 100 ms (attempt 1/10) Feb 17 13:12:14 volumio volumio[3307]: info: FusionDsp - Clipping Monitor started Feb 17 13:12:19 volumio go-librespot[5918]: time="2026-02-17T13:12:19+08:00" level=trace msg="sent dealer ping" Feb 17 13:12:19 volumio go-librespot[5918]: time="2026-02-17T13:12:19+08:00" level=trace msg="received dealer pong" Feb 17 13:12:20 volumio volumio[3307]: info: VolumeController::SetAlsaVolume51 Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:20 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:20 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:20 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:20 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:20 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Feb 17 13:12:20 volumio volumio[3307]: SPOTIFY: SPOTIFY VOLUME 100 Feb 17 13:12:20 volumio volumio[3307]: SPOTIFY: VOLUMIO VOLUME 51 Feb 17 13:12:20 volumio volumio[3307]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 17 13:12:20 volumio volumio[3307]: info: Setting Spotify Volume from Volumio: 51 Feb 17 13:12:20 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:20 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:20 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:20 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:20 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:20 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:20 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:20 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 51 Feb 17 13:12:22 volumio systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories... Feb 17 13:12:22 volumio systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully. Feb 17 13:12:22 volumio systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories. Feb 17 13:12:22 volumio systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully. Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: SETTING SPOTIFY VOLUME 51 Feb 17 13:12:22 volumio volumio[3307]: info: Sending Spotify command with payload to local API: /player/volume Feb 17 13:12:22 volumio go-librespot[5918]: time="2026-02-17T13:12:22+08:00" level=debug msg="update volume requested to 33422/65535" Feb 17 13:12:22 volumio go-librespot[5918]: time="2026-02-17T13:12:22+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 17 13:12:22 volumio go-librespot[5918]: time="2026-02-17T13:12:22+08:00" level=trace msg="emitting websocket event: volume" Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: received: {"type":"volume","data":{"value":51,"max":100}} Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: RECEIVED SPOTIFY VOLUME 51 Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: received: {"type":"volume","data":{"value":51,"max":100}} Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: RECEIVED SPOTIFY VOLUME 51 Feb 17 13:12:22 volumio volumio[3307]: info: VolumeController::SetAlsaVolume47 Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:22 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:22 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:22 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:22 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: SPOTIFY VOLUME 51 Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: VOLUMIO VOLUME 47 Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 17 13:12:22 volumio volumio[3307]: info: Setting Spotify Volume from Volumio: 47 Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:22 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:22 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::servicePushState Feb 17 13:12:22 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:22 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:22 volumio volumio[3307]: info: FusionDsp - Volumio is playing Feb 17 13:12:22 volumio volumio[3307]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 17 13:12:24 volumio volumio[3307]: SPOTIFY: SETTING SPOTIFY VOLUME 47 Feb 17 13:12:24 volumio volumio[3307]: info: Sending Spotify command with payload to local API: /player/volume Feb 17 13:12:24 volumio go-librespot[5918]: time="2026-02-17T13:12:24+08:00" level=debug msg="update volume requested to 30801/65535" Feb 17 13:12:24 volumio go-librespot[5918]: time="2026-02-17T13:12:24+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 17 13:12:24 volumio go-librespot[5918]: time="2026-02-17T13:12:24+08:00" level=trace msg="emitting websocket event: volume" Feb 17 13:12:24 volumio volumio[3307]: SPOTIFY: received: {"type":"volume","data":{"value":47,"max":100}} Feb 17 13:12:24 volumio volumio[3307]: SPOTIFY: RECEIVED SPOTIFY VOLUME 47 Feb 17 13:12:24 volumio volumio[3307]: SPOTIFY: received: {"type":"volume","data":{"value":47,"max":100}} Feb 17 13:12:24 volumio volumio[3307]: SPOTIFY: RECEIVED SPOTIFY VOLUME 47 Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Feb 17 13:12:25 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Feb 17 13:12:45 volumio volumio[3307]: info: CALLMETHOD: audio_interface alsa_controller saveVolumeOptions [object Object] Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveVolumeOptions Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:45 volumio volumio[3307]: info: Restoring Previous Volume level: 47 false true Feb 17 13:12:45 volumio volumio[3307]: info: VolumeController::SetAlsaVolume100 Feb 17 13:12:45 volumio volumio[3307]: info: Enable softmixer device for audio device number 5 Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::volumioStop Feb 17 13:12:45 volumio volumio[3307]: info: CoreStateMachine::stop Feb 17 13:12:45 volumio volumio[3307]: info: CoreStateMachine::serviceStop Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::serviceStop Feb 17 13:12:45 volumio volumio[3307]: info: [yt-cast-receiver] Player.stop() Feb 17 13:12:45 volumio volumio[3307]: info: Enable softmixer device for audio device undefined Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::volumioUpdateVolumeSettings Feb 17 13:12:45 volumio volumio[3307]: info: Updating Volume Controller Parameters: Device: 5 Name: QUAD USB Audio 2.0 Mixer: QUAD Audio 2.0 Output Max Vol: 100 Vol Curve; logarithmic Vol Steps: 5 Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Feb 17 13:12:45 volumio volumio[3307]: info: Disabling external Volume Control Feb 17 13:12:45 volumio volumio[3307]: info: Output device has changed, restarting MPD Feb 17 13:12:45 volumio volumio[3307]: info: Output device has changed, restarting Shairport Sync Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 17 13:12:45 volumio sudo[6731]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 17 13:12:45 volumio sudo[6733]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 17 13:12:45 volumio sudo[6733]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 13:12:45 volumio volumio[3307]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 17 13:12:45 volumio volumio[3307]: info: Volume configurations have been set Feb 17 13:12:45 volumio sudo[6731]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 17 13:12:45 volumio sudo[6731]: pam_unix(sudo:session): session closed for user root Feb 17 13:12:45 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::volumioUpdateVolumeSettings Feb 17 13:12:45 volumio volumio[3307]: info: Updating Volume Controller Parameters: Device: 5 Name: QUAD USB Audio 2.0 Mixer: QUAD Audio 2.0 Output Max Vol: 100 Vol Curve; logarithmic Vol Steps: 5 Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Feb 17 13:12:45 volumio volumio[3307]: info: Disabling external Volume Control Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::volumioGetState Feb 17 13:12:45 volumio volumio[3307]: info: CoreStateMachine::pushState Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 17 13:12:45 volumio volumio[3307]: info: CoreCommandRouter::volumioPushState Feb 17 13:12:45 volumio systemd[1]: mpd.service: Deactivated successfully. Feb 17 13:12:45 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Feb 17 13:12:45 volumio systemd[1]: mpd.service: Consumed 1.101s CPU time. Feb 17 13:12:45 volumio systemd[1]: mpd.socket: Deactivated successfully. Feb 17 13:12:45 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Feb 17 13:12:45 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Feb 17 13:12:45 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Feb 17 13:12:45 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Feb 17 13:12:45 volumio volumio[3307]: error: [ytcr] MPD error: Feb 17 13:12:45 volumio volumio[3307]: (AssertionError) The expression evaluated to a falsy value: Feb 17 13:12:45 volumio volumio[3307]: assert.ok(this.idling) Feb 17 13:12:45 volumio volumio[3307]: AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value: Feb 17 13:12:45 volumio volumio[3307]: assert.ok(this.idling) Feb 17 13:12:45 volumio volumio[3307]: at MPDClient.sendCommand (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:62:12) Feb 17 13:12:45 volumio volumio[3307]: at MPDPlayer. (/data/plugins/music_service/ytcr/node_modules/mpd-api/lib/api/index.js:60:16) Feb 17 13:12:45 volumio volumio[3307]: at /data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:290:13 Feb 17 13:12:45 volumio volumio[3307]: at new Promise () Feb 17 13:12:45 volumio volumio[3307]: at MPDPlayer.resolveOnMPDStatusChanged (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:269:16) Feb 17 13:12:45 volumio volumio[3307]: at MPDPlayer.doStop (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:158:37) Feb 17 13:12:45 volumio volumio[3307]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Feb 17 13:12:45 volumio volumio[3307]: at async MPDPlayer.stop (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/lib/Player.js:121:24) Feb 17 13:12:45 volumio volumio[3307]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 13:12:45 volumio volumio[3307]: MPDError: Not connected Feb 17 13:12:45 volumio volumio[3307]: at MPDClient.send (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:101:13) Feb 17 13:12:45 volumio volumio[3307]: at MPDClient.sendCommand (/data/plugins/music_service/ytcr/node_modules/mpd2/lib/index.js:65:10) Feb 17 13:12:45 volumio volumio[3307]: at Object.get (/data/plugins/music_service/ytcr/node_modules/mpd-api/lib/api/index.js:60:16) Feb 17 13:12:45 volumio volumio[3307]: at MPDPlayer.getVolumioState (/data/plugins/music_service/ytcr/dist/lib/MPDPlayer.js:297:100) Feb 17 13:12:45 volumio volumio[3307]: at ControllerYTCR.pushState (/data/plugins/music_service/ytcr/dist/index.js:566:104) Feb 17 13:12:45 volumio volumio[3307]: at /data/plugins/music_service/ytcr/dist/index.js:308:28 Feb 17 13:12:45 volumio volumio[3307]: at CoreCommandRouter.callCallback (/volumio/app/index.js:214:9) Feb 17 13:12:45 volumio volumio[3307]: at CoreCommandRouter.volumioupdatevolume (/volumio/app/index.js:143:8) Feb 17 13:12:45 volumio volumio[3307]: at Promise._successFn (/volumio/app/index.js:137:16) Feb 17 13:12:45 volumio volumio[3307]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Feb 17 13:12:45 volumio volumio[3307]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) { Feb 17 13:12:45 volumio volumio[3307]: code: 'ENOTCONNECTED' Feb 17 13:12:45 volumio volumio[3307]: } Feb 17 13:12:45 volumio volumio[3307]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 17 13:12:45 volumio sudo[6751]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 17 13:12:45 volumio sudo[6751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Feb 17 13:12:45 volumio sudo[6751]: pam_unix(sudo:session): session closed for user root Feb 17 13:12:45 volumio sudo[6768]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-17 13:11' Feb 17 13:12:45 volumio sudo[6768]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:31:57 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6759e875c98b942866984e844891d6c1"