-- Logs begin at Thu 2019-02-14 07:12:00 -03, end at Wed 2025-09-10 13:16:34 -03. -- Sep 10 13:15:00 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 10 13:15:00 volumio volumio[1071]: info: CURURI: playlists/Casa Sep 10 13:15:00 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:15:00 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$1 Sep 10 13:15:00 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$2 Sep 10 13:15:00 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$7$0 Sep 10 13:15:00 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$E Sep 10 13:15:00 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$1 in service upnp_browser Sep 10 13:15:00 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$2 in service upnp_browser Sep 10 13:15:01 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$7$0 in service upnp_browser Sep 10 13:15:01 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$E in service upnp_browser Sep 10 13:15:09 volumio kernel: hwmon hwmon1: Voltage normalised Sep 10 13:15:09 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: last_100 , handleBrowseUri Sep 10 13:15:09 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$2F$0 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$109$10 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$30$2 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$3F Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$109$A Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$7E$B Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$109$C Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$109$B Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$7E$9 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$7E$0 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$15 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$D Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$2 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$10 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$12 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$9 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$5 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$F Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$3 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$8 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$1 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$B Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$4 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$3A Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$3B Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$26 Sep 10 13:15:09 volumio volumio[1071]: info: Preloading song: upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$29 Sep 10 13:15:09 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$2F$0 in service upnp_browser Sep 10 13:15:09 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$109$10 in service upnp_browser Sep 10 13:15:09 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$30$2 in service upnp_browser Sep 10 13:15:09 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$3F in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$109$A in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$7E$B in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$109$C in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$109$B in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$7E$9 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$7E$0 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$15 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$D in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$2 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$10 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$12 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$9 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$5 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$F in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$3 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$8 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$1 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$B in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$88$4 in service upnp_browser Sep 10 13:15:10 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$3A in service upnp_browser Sep 10 13:15:11 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$3B in service upnp_browser Sep 10 13:15:11 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$26 in service upnp_browser Sep 10 13:15:11 volumio volumio[1071]: info: Exploding uri upnp/folder/http://192.167.2.1:8200/ctl/ContentDir@64$2$29 in service upnp_browser Sep 10 13:15:11 volumio kernel: hwmon hwmon1: Undervoltage detected! Sep 10 13:15:18 volumio go-librespot[1297]: time="2025-09-10T13:15:18-03:00" level=trace msg="sent dealer ping" Sep 10 13:15:18 volumio go-librespot[1297]: time="2025-09-10T13:15:18-03:00" level=trace msg="received dealer pong" Sep 10 13:15:23 volumio volumio[1071]: info: CoreCommandRouter::volumioPlay Sep 10 13:15:23 volumio volumio[1071]: info: CoreStateMachine::play index undefined Sep 10 13:15:23 volumio volumio[1071]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 10 13:15:23 volumio volumio[1071]: info: CorePlayQueue::getTrack 2 Sep 10 13:15:23 volumio volumio[1071]: info: CoreStateMachine::startPlaybackTimer Sep 10 13:15:23 volumio volumio[1071]: info: CorePlayQueue::getTrack 2 Sep 10 13:15:23 volumio volumio[1071]: info: [1757520923901] ControllerSpotify::clearAddPlayTrack Sep 10 13:15:23 volumio volumio[1071]: info: Sending Spotify command with payload to local API: /player/play Sep 10 13:15:24 volumio go-librespot[1297]: time="2025-09-10T13:15:24-03:00" level=debug msg="resolved context of track" uri="spotify:track:1rh4kDY9T4fHVDum8Foi5k" Sep 10 13:15:24 volumio go-librespot[1297]: time="2025-09-10T13:15:24-03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:1rh4kDY9T4fHVDum8Foi5k" Sep 10 13:15:24 volumio go-librespot[1297]: time="2025-09-10T13:15:24-03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:1rh4kDY9T4fHVDum8Foi5k" Sep 10 13:15:24 volumio go-librespot[1297]: time="2025-09-10T13:15:24-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 10 13:15:24 volumio go-librespot[1297]: time="2025-09-10T13:15:24-03:00" level=trace msg="emitting websocket event: will_play" Sep 10 13:15:24 volumio volumio[1071]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1rh4kDY9T4fHVDum8Foi5k","play_origin":"go-librespot"}} Sep 10 13:15:24 volumio go-librespot[1297]: time="2025-09-10T13:15:24-03:00" level=debug msg="selected format OGG_VORBIS_320 (2a2ddec696f2c95807ebba55eafc7e066da0ad9a)" uri="spotify:track:1rh4kDY9T4fHVDum8Foi5k" Sep 10 13:15:24 volumio go-librespot[1297]: time="2025-09-10T13:15:24-03:00" level=debug msg="requested aes key for file 2a2ddec696f2c95807ebba55eafc7e066da0ad9a, gid: 1rh4kDY9T4fHVDum8Foi5k" Sep 10 13:15:24 volumio go-librespot[1297]: time="2025-09-10T13:15:24-03:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:1rh4kDY9T4fHVDum8Foi5k: failed retrieving audio key: failed retrieving aes key with code 1" Sep 10 13:15:24 volumio volumio[1071]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Sep 10 13:15:28 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:15:28 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:15:29 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:15:30 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:15:47 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 10 13:15:47 volumio volumio[1071]: info: CURURI: music-library Sep 10 13:15:47 volumio volumio[1071]: error: Failed LSINFO: null Sep 10 13:15:47 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:15:48 volumio go-librespot[1297]: time="2025-09-10T13:15:48-03:00" level=trace msg="sent dealer ping" Sep 10 13:15:48 volumio go-librespot[1297]: time="2025-09-10T13:15:48-03:00" level=trace msg="received dealer pong" Sep 10 13:15:59 volumio kernel: hwmon hwmon1: Voltage normalised Sep 10 13:16:01 volumio kernel: hwmon hwmon1: Undervoltage detected! Sep 10 13:16:02 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Sep 10 13:16:02 volumio volumio[1071]: info: CURURI: playlists Sep 10 13:16:02 volumio volumio[1071]: info: Listing playlists Sep 10 13:16:02 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:16:05 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:16:05 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:16:10 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:16:10 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:16:10 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:16:11 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:16:13 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:16:13 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:16:17 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:16:17 volumio volumio[1071]: info: Preload queue cleared Sep 10 13:16:18 volumio go-librespot[1297]: time="2025-09-10T13:16:18-03:00" level=trace msg="received accesspoint ping" Sep 10 13:16:18 volumio go-librespot[1297]: time="2025-09-10T13:16:18-03:00" level=trace msg="received accesspoint pong ack" Sep 10 13:16:18 volumio go-librespot[1297]: time="2025-09-10T13:16:18-03:00" level=trace msg="sent dealer ping" Sep 10 13:16:18 volumio go-librespot[1297]: time="2025-09-10T13:16:18-03:00" level=trace msg="received dealer pong" Sep 10 13:16:32 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:16:32 volumio volumio[1071]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Sep 10 13:16:32 volumio volumio[1071]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 10 13:16:32 volumio volumio[1071]: TypeError: Cannot read property 'length' of undefined Sep 10 13:16:32 volumio volumio[1071]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Sep 10 13:16:32 volumio volumio[1071]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Sep 10 13:16:32 volumio volumio[1071]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Sep 10 13:16:32 volumio volumio[1071]: at Parser.emit (events.js:315:20) Sep 10 13:16:32 volumio volumio[1071]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Sep 10 13:16:32 volumio volumio[1071]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Sep 10 13:16:32 volumio volumio[1071]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Sep 10 13:16:32 volumio volumio[1071]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Sep 10 13:16:32 volumio volumio[1071]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Sep 10 13:16:32 volumio volumio[1071]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Sep 10 13:16:32 volumio volumio[1071]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Sep 10 13:16:32 volumio volumio[1071]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Sep 10 13:16:32 volumio volumio[1071]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Sep 10 13:16:32 volumio volumio[1071]: at IncomingMessage.emit (events.js:327:22) Sep 10 13:16:32 volumio volumio[1071]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 10 13:16:32 volumio volumio[1071]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 10 13:16:33 volumio volumio[1071]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 10 13:16:34 volumio sudo[8375]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-10 13:15 Sep 10 13:16:34 volumio sudo[8375]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"