-- Logs begin at Thu 2025-06-26 16:03:45 UTC, end at Thu 2025-07-17 15:58:37 UTC. -- Jul 17 15:58:05 kiwibox ntpd[553]: receive: Unexpected origin timestamp 0xec07ee54.3138fa3e does not match aorg 0000000000.00000000 from server@185.255.121.15 xmt 0xec239c0d.58c965e6 Jul 17 15:58:05 kiwibox ntpd[553]: receive: Unexpected origin timestamp 0xec07ee54.315bd39b does not match aorg 0000000000.00000000 from server@194.59.205.229 xmt 0xec239c0d.594d4744 Jul 17 15:58:05 kiwibox ntpd[553]: receive: Unexpected origin timestamp 0xec07ee54.3126b28e does not match aorg 0000000000.00000000 from server@109.123.244.54 xmt 0xec239c0d.5a83702e Jul 17 15:58:05 kiwibox systemd[1]: Starting Daily apt download activities... Jul 17 15:58:05 kiwibox volumio[809]: info: ___________ START PLUGINS ___________ Jul 17 15:58:05 kiwibox volumio[809]: info: ControllerMpd::onStart: Initializing MPD Jul 17 15:58:05 kiwibox volumio[809]: info: Creating MPD Configuration file Jul 17 15:58:05 kiwibox sudo[936]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 17 15:58:05 kiwibox sudo[936]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 17 15:58:06 kiwibox sudo[939]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 17 15:58:06 kiwibox sudo[936]: pam_unix(sudo:session): session closed for user root Jul 17 15:58:06 kiwibox sudo[939]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 17 15:58:06 kiwibox volumio[809]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 17 15:58:06 kiwibox volumio[809]: info: [1752767886484] CoreMusicLibrary::Adding element Last_100 Jul 17 15:58:06 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 17 15:58:06 kiwibox volumio[809]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 17 15:58:06 kiwibox systemd[1]: Listening on mpd.socket. Jul 17 15:58:06 kiwibox volumio[809]: info: [1752767886868] CoreMusicLibrary::Adding element Webradio Jul 17 15:58:06 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 17 15:58:06 kiwibox systemd[1]: Starting Music Player Daemon... Jul 17 15:58:07 kiwibox sudo[944]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 17 15:58:07 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 17 15:58:07 kiwibox sudo[944]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 17 15:58:07 kiwibox sudo[950]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 17 15:58:07 kiwibox sudo[950]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 17 15:58:07 kiwibox sudo[944]: pam_unix(sudo:session): session closed for user root Jul 17 15:58:07 kiwibox volumio[809]: info: Initializing BBC Radios Jul 17 15:58:07 kiwibox systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Jul 17 15:58:07 kiwibox systemd[1]: mpd.service: Succeeded. Jul 17 15:58:07 kiwibox systemd[1]: Stopped Music Player Daemon. Jul 17 15:58:07 kiwibox volumio[809]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Jul 17 15:58:07 kiwibox systemd[1]: Starting Music Player Daemon... Jul 17 15:58:07 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 17 15:58:08 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 17 15:58:08 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 17 15:58:08 kiwibox sudo[968]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jul 17 15:58:08 kiwibox sudo[968]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 17 15:58:09 kiwibox sudo[968]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Jul 17 15:58:09 kiwibox sudo[968]: pam_unix(sudo:session): session closed for user root Jul 17 15:58:09 kiwibox volumio[809]: info: Creating Spotify config file Jul 17 15:58:09 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:09 kiwibox volumio[809]: Starting albumart workers Jul 17 15:58:11 kiwibox volumio[809]: info: Volumio Calling Home Jul 17 15:58:16 kiwibox volumio[809]: info: MPD Permissions set Jul 17 15:58:16 kiwibox volumio[809]: info: MPD Permissions set Jul 17 15:58:17 kiwibox volumio[809]: info: Discovery: A device disappeared from network Jul 17 15:58:17 kiwibox volumio[809]: info: Discovery: Device radio disappeared from network Jul 17 15:58:17 kiwibox volumio[809]: info: Discovery: Disconnected from remote: 192.168.10.12 Jul 17 15:58:17 kiwibox volumio[809]: info: Volumio called home Jul 17 15:58:17 kiwibox volumio[809]: info: Spotify config file written Jul 17 15:58:18 kiwibox volumio[809]: info: Discovery: A device disappeared from network Jul 17 15:58:18 kiwibox sudo[988]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 17 15:58:18 kiwibox sudo[988]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 17 15:58:19 kiwibox systemd[1]: Started go-librespot Daemon. Jul 17 15:58:19 kiwibox go-librespot[996]: Librespot-go daemon starting... Jul 17 15:58:19 kiwibox sudo[988]: pam_unix(sudo:session): session closed for user root Jul 17 15:58:19 kiwibox volumio-remote-updater[448]: [2025-07-17 15:58:19] [connect] Successful connection Jul 17 15:58:20 kiwibox volumio[809]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 17 15:58:20 kiwibox go-librespot[996]: time="2025-07-17T15:58:20Z" level=info msg="generated new device id: 9aab7a91a9b4625aa414b4dd7081a32af791a225" Jul 17 15:58:20 kiwibox go-librespot[996]: time="2025-07-17T15:58:20Z" level=debug msg="stored credentials found for mmooppaa" Jul 17 15:58:20 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:20 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:20 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:20 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:20 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:20 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:20 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:21 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:22 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 17 15:58:22 kiwibox volumio[809]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 17 15:58:22 kiwibox volumio[809]: info: Jul 17 15:58:22 kiwibox volumio[809]: ---------------------------- Client requests Volumio Play Playlist jaime_2025-03 Jul 17 15:58:22 kiwibox volumio[809]: info: Play playlist jaime_2025-03 Jul 17 15:58:24 kiwibox systemd[1]: apt-daily.service: Succeeded. Jul 17 15:58:24 kiwibox systemd[1]: Started Daily apt download activities. Jul 17 15:58:24 kiwibox systemd[1]: Starting Daily apt upgrade and clean activities... Jul 17 15:58:25 kiwibox go-librespot[996]: time="2025-07-17T15:58:25Z" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 17 15:58:25 kiwibox go-librespot[996]: time="2025-07-17T15:58:25Z" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jul 17 15:58:25 kiwibox go-librespot[996]: time="2025-07-17T15:58:25Z" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jul 17 15:58:25 kiwibox go-librespot[996]: time="2025-07-17T15:58:25Z" level=debug msg="zeroconf server listening on port 38307" Jul 17 15:58:26 kiwibox go-librespot[996]: time="2025-07-17T15:58:26Z" level=debug msg="obtained new client token: AAAi/qNTj/FqUr08kW4fUD9Z1cy9f95tazpbnHCzi3xgD3frhyt9EdE/v+g1eUWIFy7mEnIYzocs8u41KJPcoQf79SRDpK6a7z0HgAZhrle3Wkncy2Ka3sYV3A1ccy+Rzh1gKYr0PqKxid/Zs/prgB8sNlV7/h9pbglQ0VVC8P8QnCaZI7fPQxrXK2sfwoYUKI1NPtcx0nm7ScrNyWQGe/DC5j1QZ+9hkFGzMiO9Br+bfFP0HCrfzm7XsA==" Jul 17 15:58:26 kiwibox go-librespot[996]: time="2025-07-17T15:58:26Z" level=debug msg="completed keyexchange" Jul 17 15:58:26 kiwibox volumio[809]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 17 15:58:26 kiwibox volumio[809]: SPOTIFY: BQCsgoiZWkQCSx4bFX3NudJhD_R55sZYXpQGTjIWI5sUdSLRW_1wQ7LA1AsQzfSEYlJlW-lPqYciT9DhcCRTVegUMZJWo5lcJ8gtnD78N9UHNJ6XS5iNdwp3iJkcwqH5E_TUB3as2kvCN7Db8G4JCmh0SFw9pqIVlhPor-DUQLNtbca9eZviPZNuqPkGbpvZSH8MPJvBNW9sg3yExLa2Z4RKO_uoJGkkgzyHhk0ZpSlekoHOrEEKuvNhN2ieiDTfMl2ReMwOgKcDcY8RlJbupU3T Jul 17 15:58:26 kiwibox volumio[809]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 17 15:58:26 kiwibox volumio[809]: info: New Spotify access token = BQCsgoiZWkQCSx4bFX3NudJhD_R55sZYXpQGTjIWI5sUdSLRW_1wQ7LA1AsQzfSEYlJlW-lPqYciT9DhcCRTVegUMZJWo5lcJ8gtnD78N9UHNJ6XS5iNdwp3iJkcwqH5E_TUB3as2kvCN7Db8G4JCmh0SFw9pqIVlhPor-DUQLNtbca9eZviPZNuqPkGbpvZSH8MPJvBNW9sg3yExLa2Z4RKO_uoJGkkgzyHhk0ZpSlekoHOrEEKuvNhN2ieiDTfMl2ReMwOgKcDcY8RlJbupU3T Jul 17 15:58:26 kiwibox volumio[809]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 17 15:58:27 kiwibox go-librespot[996]: time="2025-07-17T15:58:27Z" level=debug msg="completed challenge" Jul 17 15:58:27 kiwibox go-librespot[996]: time="2025-07-17T15:58:27Z" level=debug msg="authenticated as mmooppaa" Jul 17 15:58:27 kiwibox volumio[809]: info: Discovery: adding 87529fed-4265-4d44-93aa-921f483987c5 Jul 17 15:58:27 kiwibox volumio[809]: info: Discovery: Found device Volumio Jul 17 15:58:27 kiwibox volumio[809]: info: CoreCommandRouter::volumioGetState Jul 17 15:58:27 kiwibox volumio[809]: info: CorePlayQueue::getTrack 0 Jul 17 15:58:27 kiwibox go-librespot[996]: time="2025-07-17T15:58:27Z" level=debug msg="authenticated as mmooppaa" Jul 17 15:58:27 kiwibox volumio[809]: info: CoreCommandRouter::volumioGetState Jul 17 15:58:27 kiwibox volumio[809]: info: CorePlayQueue::getTrack 0 Jul 17 15:58:27 kiwibox go-librespot[996]: time="2025-07-17T15:58:27Z" level=debug msg="dealer connection opened" Jul 17 15:58:27 kiwibox go-librespot[996]: time="2025-07-17T15:58:27Z" level=debug msg="initializing zeroconf session, username: mmooppaa" Jul 17 15:58:28 kiwibox go-librespot[996]: time="2025-07-17T15:58:28Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 17 15:58:28 kiwibox go-librespot[996]: time="2025-07-17T15:58:28Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 17 15:58:28 kiwibox go-librespot[996]: time="2025-07-17T15:58:28Z" level=debug msg="received connection id: NTZkNGY2YjAtZmI0Yi00YjZiLTljNDQtYjhjNGYzMjZiZTQ1K2RlYWxlcit0Y3A6Ly8wYWIxNTIwZi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRDExQjg0QzBCRDQ5MjU4MDI5QzI1MEI3QkVENzRFNTE4QkRBOUNBRUNGRkM1QzU2MTM5OTY0M0E5RDUxN0IzMw==" Jul 17 15:58:28 kiwibox volumio[809]: info: Discovery: adding ed6b0661-a910-464e-be9a-ab786899a7e7 Jul 17 15:58:28 kiwibox volumio[809]: info: Discovery: Found device radio Jul 17 15:58:28 kiwibox volumio[809]: info: Discovery: Connecting to remote: 192.168.10.12 Jul 17 15:58:28 kiwibox go-librespot[996]: time="2025-07-17T15:58:28Z" level=debug msg="put connect state because NEW_DEVICE" Jul 17 15:58:28 kiwibox go-librespot[996]: time="2025-07-17T15:58:28Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 17 15:58:28 kiwibox go-librespot[996]: time="2025-07-17T15:58:28Z" level=debug msg="autoplay enabled: false" Jul 17 15:58:28 kiwibox go-librespot[996]: time="2025-07-17T15:58:28Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 17 15:58:28 kiwibox go-librespot[996]: time="2025-07-17T15:58:28Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 17 15:58:28 kiwibox volumio[809]: info: go-librespot daemon successfully initialized Jul 17 15:58:28 kiwibox volumio[809]: info: CoreCommandRouter::volumioClearQueue Jul 17 15:58:28 kiwibox volumio[809]: info: CoreStateMachine::ClearQueue Jul 17 15:58:28 kiwibox volumio[809]: info: CoreStateMachine::stop Jul 17 15:58:28 kiwibox volumio[809]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 17 15:58:28 kiwibox volumio[809]: info: CorePlayQueue::clearPlayQueue Jul 17 15:58:28 kiwibox volumio[809]: info: CorePlayQueue::saveQueue Jul 17 15:58:28 kiwibox volumio[809]: info: CoreCommandRouter::volumioPushState Jul 17 15:58:29 kiwibox volumio[809]: info: CoreCommandRouter::volumioPushQueue Jul 17 15:58:29 kiwibox volumio[809]: info: CoreCommandRouter::volumioAddQueueItems Jul 17 15:58:29 kiwibox volumio[809]: info: CoreStateMachine::addQueueItems Jul 17 15:58:29 kiwibox volumio[809]: info: CorePlayQueue::addQueueItems Jul 17 15:58:29 kiwibox volumio[809]: info: Preload queue cleared Jul 17 15:58:29 kiwibox volumio[809]: info: Adding Item to queue: INTERNAL/Mes premier j aime lire/2025-03 Emil et Margot - L etrange majordome.m4a Jul 17 15:58:29 kiwibox volumio[809]: info: Exploding uri INTERNAL/Mes premier j aime lire/2025-03 Emil et Margot - L etrange majordome.m4a in service mpd Jul 17 15:58:29 kiwibox volumio[809]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 17 15:58:29 kiwibox volumio[809]: TypeError: Cannot read property 'then' of undefined Jul 17 15:58:29 kiwibox volumio[809]: at ControllerMpd.scanFolder (/volumio/app/plugins/music_service/mpd/index.js:2527:19) Jul 17 15:58:29 kiwibox volumio[809]: at ControllerMpd.explodeUri (/volumio/app/plugins/music_service/mpd/index.js:2325:21) Jul 17 15:58:29 kiwibox volumio[809]: at CoreCommandRouter.explodeUriFromService (/volumio/app/index.js:1365:16) Jul 17 15:58:29 kiwibox volumio[809]: at CorePlayQueue.explodeUriFromCache (/volumio/app/playqueue.js:123:24) Jul 17 15:58:29 kiwibox volumio[809]: at CorePlayQueue.explodeUri (/volumio/app/playqueue.js:181:19) Jul 17 15:58:29 kiwibox volumio[809]: at CorePlayQueue.addQueueItems (/volumio/app/playqueue.js:223:30) Jul 17 15:58:29 kiwibox volumio[809]: at CoreStateMachine.addQueueItems (/volumio/app/statemachine.js:247:25) Jul 17 15:58:29 kiwibox volumio[809]: at CoreCommandRouter.addQueueItems (/volumio/app/index.js:447:28) Jul 17 15:58:29 kiwibox volumio[809]: at /volumio/app/playlistManager.js:726:30 Jul 17 15:58:29 kiwibox volumio[809]: at /volumio/node_modules/jsonfile/index.js:46:5 Jul 17 15:58:29 kiwibox volumio[809]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 17 15:58:34 kiwibox volumio-remote-updater[448]: [2025-07-17 15:58:34] [connect] Successful connection Jul 17 15:58:37 kiwibox sudo[1082]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-17 15:57 Jul 17 15:58:37 kiwibox sudo[1082]: 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"