-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Fri 2025-03-14 17:23:07 CET. -- Mar 14 17:22:01 volumio volumio[953]: SPOTIFY: SETTING SPOTIFY VOLUME 80 Mar 14 17:22:01 volumio volumio[953]: info: Sending Spotify command with payload to local API: /player/volume Mar 14 17:22:01 volumio go-librespot[1243]: time="2025-03-14T17:22:01+01:00" level=debug msg="update volume to 52428/65535" Mar 14 17:22:01 volumio volumio[953]: info: VolumeController::SetAlsaVolume- Mar 14 17:22:01 volumio volumio[953]: info: CoreStateMachine::pushState Mar 14 17:22:01 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 14 17:22:01 volumio volumio[953]: info: CoreCommandRouter::volumioPushState Mar 14 17:22:01 volumio volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 80 Mar 14 17:22:02 volumio go-librespot[1243]: time="2025-03-14T17:22:02+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 14 17:22:02 volumio go-librespot[1243]: time="2025-03-14T17:22:02+01:00" level=trace msg="emitting websocket event: volume" Mar 14 17:22:02 volumio volumio[953]: SPOTIFY: received: {"type":"volume","data":{"value":80,"max":100}} Mar 14 17:22:02 volumio volumio[953]: SPOTIFY: RECEIVED SPOTIFY VOLUME 80 Mar 14 17:22:15 volumio nmbd[751]: [2025/03/14 17:22:15.362395, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Mar 14 17:22:15 volumio nmbd[751]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.146 for name WORKGROUP<1d>. Mar 14 17:22:15 volumio nmbd[751]: This response was from IP 192.168.1.10, reporting an IP address of 192.168.1.10. Mar 14 17:22:17 volumio go-librespot[1243]: time="2025-03-14T17:22:17+01:00" level=debug msg="update volume to 31457/65535" Mar 14 17:22:18 volumio go-librespot[1243]: time="2025-03-14T17:22:18+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 14 17:22:18 volumio go-librespot[1243]: time="2025-03-14T17:22:18+01:00" level=trace msg="emitting websocket event: volume" Mar 14 17:22:18 volumio volumio[953]: SPOTIFY: received: {"type":"volume","data":{"value":49,"max":100}} Mar 14 17:22:18 volumio volumio[953]: SPOTIFY: RECEIVED SPOTIFY VOLUME 49 Mar 14 17:22:18 volumio volumio[953]: info: Setting Volumio Volume from Spotify: 49 Mar 14 17:22:18 volumio volumio[953]: info: VolumeController::SetAlsaVolume49 Mar 14 17:22:18 volumio volumio[953]: info: CoreStateMachine::pushState Mar 14 17:22:18 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 14 17:22:18 volumio volumio[953]: info: CoreCommandRouter::volumioPushState Mar 14 17:22:18 volumio volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Mar 14 17:22:19 volumio go-librespot[1243]: time="2025-03-14T17:22:19+01:00" level=debug msg="update volume to 35389/65535" Mar 14 17:22:20 volumio go-librespot[1243]: time="2025-03-14T17:22:20+01:00" level=debug msg="update volume to 42598/65535" Mar 14 17:22:21 volumio go-librespot[1243]: time="2025-03-14T17:22:21+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 14 17:22:21 volumio go-librespot[1243]: time="2025-03-14T17:22:21+01:00" level=trace msg="emitting websocket event: volume" Mar 14 17:22:21 volumio volumio[953]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Mar 14 17:22:21 volumio volumio[953]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Mar 14 17:22:21 volumio volumio[953]: info: Setting Volumio Volume from Spotify: 66 Mar 14 17:22:21 volumio volumio[953]: info: VolumeController::SetAlsaVolume66 Mar 14 17:22:21 volumio volumio[953]: info: CoreStateMachine::pushState Mar 14 17:22:21 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 14 17:22:21 volumio volumio[953]: info: CoreCommandRouter::volumioPushState Mar 14 17:22:21 volumio volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Mar 14 17:22:22 volumio go-librespot[1243]: time="2025-03-14T17:22:22+01:00" level=debug msg="update volume to 44564/65535" Mar 14 17:22:23 volumio go-librespot[1243]: time="2025-03-14T17:22:23+01:00" level=debug msg="update volume to 50462/65535" Mar 14 17:22:24 volumio go-librespot[1243]: time="2025-03-14T17:22:24+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 14 17:22:24 volumio go-librespot[1243]: time="2025-03-14T17:22:24+01:00" level=trace msg="emitting websocket event: volume" Mar 14 17:22:24 volumio volumio[953]: SPOTIFY: received: {"type":"volume","data":{"value":78,"max":100}} Mar 14 17:22:24 volumio volumio[953]: SPOTIFY: RECEIVED SPOTIFY VOLUME 78 Mar 14 17:22:24 volumio volumio[953]: info: Setting Volumio Volume from Spotify: 78 Mar 14 17:22:24 volumio volumio[953]: info: VolumeController::SetAlsaVolume78 Mar 14 17:22:24 volumio volumio[953]: info: CoreStateMachine::pushState Mar 14 17:22:24 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 14 17:22:24 volumio volumio[953]: info: CoreCommandRouter::volumioPushState Mar 14 17:22:24 volumio volumio[953]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 Mar 14 17:22:27 volumio go-librespot[1243]: time="2025-03-14T17:22:27+01:00" level=trace msg="received accesspoint ping" Mar 14 17:22:27 volumio go-librespot[1243]: time="2025-03-14T17:22:27+01:00" level=trace msg="received accesspoint pong ack" Mar 14 17:22:27 volumio go-librespot[1243]: time="2025-03-14T17:22:27+01:00" level=trace msg="sent dealer ping" Mar 14 17:22:27 volumio go-librespot[1243]: time="2025-03-14T17:22:27+01:00" level=trace msg="received dealer pong" Mar 14 17:22:27 volumio go-librespot[1243]: time="2025-03-14T17:22:27+01:00" level=debug msg="handling resume player command from 2f884d08260765e871e7c698f1d9b38c5ba99c12" Mar 14 17:22:27 volumio go-librespot[1243]: time="2025-03-14T17:22:27+01:00" level=debug msg="vorbis: corrupt or missing data in bitstream" uri="spotify:track:2LYyCjVw6pmMUHKjl6zEOZ" Mar 14 17:22:27 volumio go-librespot[1243]: time="2025-03-14T17:22:27+01:00" level=trace msg="seek to 48439ms (diff: 85ms, samples: 2136159, bytes: 1544821)" uri="spotify:track:2LYyCjVw6pmMUHKjl6zEOZ" Mar 14 17:22:27 volumio go-librespot[1243]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 14 17:22:27 volumio go-librespot[1243]: time="2025-03-14T17:22:27+01:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such device" Mar 14 17:22:28 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 14 17:22:28 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 14 17:22:28 volumio volumio[953]: info: Discovery: Getting this device information Mar 14 17:22:28 volumio volumio[953]: info: CoreCommandRouter::volumioGetState Mar 14 17:22:28 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 14 17:22:31 volumio go-librespot[1243]: time="2025-03-14T17:22:31+01:00" level=debug msg="handling resume player command from 2f884d08260765e871e7c698f1d9b38c5ba99c12" Mar 14 17:22:31 volumio go-librespot[1243]: time="2025-03-14T17:22:31+01:00" level=trace msg="seek to 48439ms (diff: 85ms, samples: 2136159, bytes: 1544821)" uri="spotify:track:2LYyCjVw6pmMUHKjl6zEOZ" Mar 14 17:22:31 volumio go-librespot[1243]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 14 17:22:31 volumio go-librespot[1243]: time="2025-03-14T17:22:31+01:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such device" Mar 14 17:22:32 volumio go-librespot[1243]: time="2025-03-14T17:22:32+01:00" level=debug msg="handling resume player command from 2f884d08260765e871e7c698f1d9b38c5ba99c12" Mar 14 17:22:32 volumio go-librespot[1243]: time="2025-03-14T17:22:32+01:00" level=trace msg="seek to 48439ms (diff: 85ms, samples: 2136159, bytes: 1544821)" uri="spotify:track:2LYyCjVw6pmMUHKjl6zEOZ" Mar 14 17:22:32 volumio go-librespot[1243]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 14 17:22:32 volumio go-librespot[1243]: time="2025-03-14T17:22:32+01:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such device" Mar 14 17:22:36 volumio go-librespot[1243]: time="2025-03-14T17:22:36+01:00" level=debug msg="handling resume player command from 2f884d08260765e871e7c698f1d9b38c5ba99c12" Mar 14 17:22:36 volumio go-librespot[1243]: time="2025-03-14T17:22:36+01:00" level=trace msg="seek to 48439ms (diff: 85ms, samples: 2136159, bytes: 1544821)" uri="spotify:track:2LYyCjVw6pmMUHKjl6zEOZ" Mar 14 17:22:36 volumio go-librespot[1243]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Mar 14 17:22:36 volumio go-librespot[1243]: time="2025-03-14T17:22:36+01:00" level=warning msg="failed handling dealer request" error="failed starting playback: ALSA error at snd_pcm_open: No such device" Mar 14 17:22:41 volumio go-librespot[1243]: time="2025-03-14T17:22:41+01:00" level=debug msg="handling play player command from 2f884d08260765e871e7c698f1d9b38c5ba99c12" Mar 14 17:22:41 volumio go-librespot[1243]: time="2025-03-14T17:22:41+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1FgnTBfUlzkeKt" Mar 14 17:22:41 volumio go-librespot[1243]: time="2025-03-14T17:22:41+01:00" level=warning msg="failed seeking to track in context spotify:playlist:37i9dQZF1FgnTBfUlzkeKt" error="failed fetching tracks for seek: failed moving to next index 0 (page 0): invalid empty page without url" uri="spotify:playlist:37i9dQZF1FgnTBfUlzkeKt" Mar 14 17:22:41 volumio go-librespot[1243]: time="2025-03-14T17:22:41+01:00" level=warning msg="failed handling dealer request" error="failed seeking to track: failed moving to start: invalid empty page without url" Mar 14 17:22:47 volumio go-librespot[1243]: time="2025-03-14T17:22:47+01:00" level=debug msg="handling update_context player command from 2f884d08260765e871e7c698f1d9b38c5ba99c12" Mar 14 17:22:47 volumio go-librespot[1243]: time="2025-03-14T17:22:47+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 14 17:22:47 volumio go-librespot[1243]: time="2025-03-14T17:22:47+01:00" level=debug msg="sending successful reply for dealer request" Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 14 17:22:47 volumio volumio[953]: info: Retrieving Cloud Streaming UI Mar 14 17:22:47 volumio volumio[953]: info: Getting Tidal Cloud Configuration Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 14 17:22:47 volumio volumio[953]: info: Getting Qobuz Cloud Configuration Mar 14 17:22:47 volumio volumio[953]: info: Asking plugin for UI Config Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 14 17:22:47 volumio volumio[953]: info: Getting Spotify Cloud Configuration Mar 14 17:22:47 volumio volumio[953]: info: Asking plugin for UI Config Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 14 17:22:47 volumio volumio[953]: info: Saving Spotify Acccount Mar 14 17:22:47 volumio volumio[953]: info: Got Tidal Cloud Configuration Mar 14 17:22:47 volumio volumio[953]: info: Got it Mar 14 17:22:47 volumio volumio[953]: info: Got it Mar 14 17:22:47 volumio volumio[953]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 14 17:22:47 volumio volumio[953]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::volumioGetBrowseSources Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::volumioGetBrowseSources Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::volumioGetBrowseSources Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Mar 14 17:22:47 volumio volumio[953]: error: updateQueue error: null Mar 14 17:22:47 volumio volumio[953]: info: ------------------------------ 63017ms Mar 14 17:22:47 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Mar 14 17:22:57 volumio go-librespot[1243]: time="2025-03-14T17:22:57+01:00" level=trace msg="sent dealer ping" Mar 14 17:22:57 volumio go-librespot[1243]: time="2025-03-14T17:22:57+01:00" level=trace msg="received dealer pong" Mar 14 17:22:58 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 14 17:22:58 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 14 17:22:58 volumio volumio[953]: info: Discovery: Getting this device information Mar 14 17:22:58 volumio volumio[953]: info: CoreCommandRouter::volumioGetState Mar 14 17:22:58 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 14 17:23:01 volumio volumio[953]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Mar 14 17:23:01 volumio volumio[953]: info: In handleBrowseUri, curUri=spotify Mar 14 17:23:02 volumio volumio[953]: info: New access token = BQDW2PWvv9CgnkW8q2C_11PVItsVduBM5YAC4huiKLFENgaNpsnb_BR7T5s1fKTd6uuXKw_sjFQ7UbVnISRea6RXnzKNf7rxOifpkgMYKyhaA89iQqd-udWmVI5UL_bAZCKUE5psUS06-cx4NS0wUTUMDg39q5ShQkPDpDtF_HD2Eyc9XESwK4ayjJHj7i1FW7PzmBrR5dEXUyddyWvgsfEk_kOrJUYe7uMiQeypWEX6sPRk1SmYbd59A-GLwh2Gzjcpp7UgM4day4gmTEFCbHHn_4Jux2V6MAjZABM Mar 14 17:23:02 volumio volumio[953]: info: New access token = BQD7hAXwnkdq-Y2KQp0pnLySwQVtuieSTg60wV77FcQjKt1kOPzFrrKFn7kXm19QmUMZCkHdoMOOoceiXannAGrwUbwlgZZyMi47fmqalrSVsKSFHmapA1jVNY44liCUEz0pmStXCYOQHxHvi3vhSChr65H9piRpVtRRAHodrHFtVE5Seb1OpK_NSPKczoLvga4SarnDMuokqD3QaEny3e7P2_WGuHGBVSapodQvZ572Xn-3fWZhplNvNkCCa8BQo-IFPeHzoT2aBT2M-BYKtBXr8Mjq2WA9hy8kFw4 Mar 14 17:23:02 volumio volumio[953]: info: New access token = BQCm1si3f9W81oSdNPdgTGlr2TV2n1M3ge5UYd9WL-mWDAEN278B9E4Vx5pFr1Y_fGpRg2pVLCOqeUp7Em1_eIhQ-HuhfahGp88eUG3xkgTLB0avo46tzG6WBUhaUE6iIxp4knj7tUXj5cJvHnMTfA2TcaAUTHnITXyZ2rNLibGB-2sHgedqEDa0q8DMkjY59_5jyn0bLbO6xoE1ZeTzS0pDuFjV6DYOfzwz25fda4eiJ6fzR2lnk05SKeGvtcQJblb4NdVPuNWhJ2Hmc9_wGPw5hULt24ruKX-uq8A Mar 14 17:23:02 volumio volumio[953]: info: Preload queue cleared Mar 14 17:23:02 volumio volumio[953]: info: Preload queue cleared Mar 14 17:23:02 volumio volumio[953]: info: Preload queue cleared Mar 14 17:23:02 volumio volumio[953]: info: Preload queue cleared Mar 14 17:23:06 volumio volumio[953]: info: Mar 14 17:23:06 volumio volumio[953]: ---------------------------- MPD announces system playlist update Mar 14 17:23:06 volumio volumio[953]: info: Ignoring MPD Status Update Mar 14 17:23:06 volumio volumio[953]: info: Mar 14 17:23:06 volumio volumio[953]: ---------------------------- MPD announces state update: player Mar 14 17:23:06 volumio volumio[953]: info: ControllerMpd::getState Mar 14 17:23:06 volumio volumio[953]: verbose: ControllerMpd::sendMpdCommand status Mar 14 17:23:06 volumio volumio[953]: info: Mar 14 17:23:06 volumio volumio[953]: ---------------------------- MPD announces system playlist update Mar 14 17:23:06 volumio volumio[953]: info: Ignoring MPD Status Update Mar 14 17:23:06 volumio volumio[953]: info: Mar 14 17:23:06 volumio volumio[953]: ---------------------------- MPD announces state update: player Mar 14 17:23:06 volumio volumio[953]: info: ControllerMpd::getState Mar 14 17:23:06 volumio volumio[953]: verbose: ControllerMpd::sendMpdCommand status Mar 14 17:23:06 volumio volumio[953]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 14 17:23:06 volumio volumio[953]: TypeError: Cannot read property 'substring' of undefined Mar 14 17:23:06 volumio volumio[953]: at /volumio/app/plugins/music_service/mpd/index.js:2827:70 Mar 14 17:23:06 volumio volumio[953]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Mar 14 17:23:06 volumio volumio[953]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Mar 14 17:23:06 volumio volumio[953]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Mar 14 17:23:06 volumio volumio[953]: at Socket.emit (events.js:315:20) Mar 14 17:23:06 volumio volumio[953]: at addChunk (internal/streams/readable.js:309:12) Mar 14 17:23:06 volumio volumio[953]: at readableAddChunk (internal/streams/readable.js:280:11) Mar 14 17:23:06 volumio volumio[953]: at Socket.Readable.push (internal/streams/readable.js:223:10) Mar 14 17:23:06 volumio volumio[953]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23) Mar 14 17:23:06 volumio volumio[953]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 14 17:23:07 volumio sudo[7526]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-14 17:22 Mar 14 17:23:07 volumio sudo[7526]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="a01a833dd28483f88cb390596f5090b7187992af" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 27 Feb 2025 11:42:54 AM CET" VOLUMIO_VERSION="3.795" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="4049a67f1c09d4a94e033ba35a80a144"