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"