-- Logs begin at Thu 2019-02-14 05:11:58 EST, end at Sat 2025-05-31 14:06:14 EDT. -- May 31 14:05:01 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:01 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:03 musicbox volumio[976]: info: VolumeController::SetAlsaVolume53 May 31 14:05:03 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:03 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:03 musicbox volumio[976]: info: CoreStateMachine::pushState May 31 14:05:03 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:03 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 14:05:03 musicbox volumio[976]: info: CoreCommandRouter::volumioPushState May 31 14:05:03 musicbox volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 53 May 31 14:05:03 musicbox volumio[976]: SPOTIFY: SPOTIFY VOLUME 100 May 31 14:05:03 musicbox volumio[976]: SPOTIFY: VOLUMIO VOLUME 53 May 31 14:05:03 musicbox volumio[976]: SPOTIFY: DELTA VOLUME ENOUGH: true May 31 14:05:03 musicbox volumio[976]: info: Setting Spotify Volume from Volumio: 53 May 31 14:05:04 musicbox volumio[976]: info: VolumeController::SetAlsaVolume41 May 31 14:05:04 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:04 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:04 musicbox volumio[976]: info: CoreStateMachine::pushState May 31 14:05:04 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:04 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 14:05:04 musicbox volumio[976]: info: CoreCommandRouter::volumioPushState May 31 14:05:04 musicbox volumio[976]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 May 31 14:05:04 musicbox volumio[976]: SPOTIFY: SPOTIFY VOLUME 53 May 31 14:05:04 musicbox volumio[976]: SPOTIFY: VOLUMIO VOLUME 41 May 31 14:05:04 musicbox volumio[976]: SPOTIFY: DELTA VOLUME ENOUGH: true May 31 14:05:04 musicbox volumio[976]: info: Setting Spotify Volume from Volumio: 41 May 31 14:05:05 musicbox volumio[976]: SPOTIFY: SETTING SPOTIFY VOLUME 41 May 31 14:05:05 musicbox volumio[976]: info: Sending Spotify command with payload to local API: /player/volume May 31 14:05:05 musicbox go-librespot[1306]: time="2025-05-31T14:05:05-04:00" level=debug msg="update volume to 26869/65535" May 31 14:05:06 musicbox go-librespot[1306]: time="2025-05-31T14:05:06-04:00" level=debug msg="put connect state because VOLUME_CHANGED" May 31 14:05:06 musicbox go-librespot[1306]: time="2025-05-31T14:05:06-04:00" level=trace msg="emitting websocket event: volume" May 31 14:05:06 musicbox volumio[976]: SPOTIFY: received: {"type":"volume","data":{"value":41,"max":100}} May 31 14:05:06 musicbox volumio[976]: SPOTIFY: RECEIVED SPOTIFY VOLUME 41 May 31 14:05:11 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:11 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:11 musicbox volumio[976]: info: Listing playlists May 31 14:05:11 musicbox volumio[976]: info: Listing playlists May 31 14:05:13 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:13 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:14 musicbox go-librespot[1306]: time="2025-05-31T14:05:14-04:00" level=trace msg="sent dealer ping" May 31 14:05:14 musicbox go-librespot[1306]: time="2025-05-31T14:05:14-04:00" level=trace msg="received dealer pong" May 31 14:05:14 musicbox go-librespot[1306]: time="2025-05-31T14:05:14-04:00" level=debug msg="fetched chunk 4/9, size: 524288" uri="spotify:track:2q2Z2A0Mt8AsWyQEdB6wuu" May 31 14:05:17 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 14:05:17 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 14:05:21 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:21 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:26 musicbox volumio[976]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/mpdoutput/volumio/buster/armhf May 31 14:05:27 musicbox volumio[976]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/mpdoutput/volumio/buster/armhf May 31 14:05:27 musicbox volumio[976]: info: Folder /tmp/plugins removed May 31 14:05:28 musicbox volumio[976]: info: Check plugin dependencies May 31 14:05:28 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 14:05:28 musicbox volumio[976]: info: Checking if plugin already exists May 31 14:05:28 musicbox volumio[976]: info: Rename folder May 31 14:05:28 musicbox volumio[976]: info: Folder /tmp/downloaded_plugin.zip removed May 31 14:05:28 musicbox volumio[976]: info: Move to category May 31 14:05:28 musicbox volumio[976]: info: Checking if install.sh is present May 31 14:05:28 musicbox volumio[976]: info: Executing install.sh May 31 14:05:28 musicbox sudo[1846]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/audio_interface/mpdoutput/install.sh May 31 14:05:28 musicbox sudo[1846]: pam_unix(sudo:session): session opened for user root by (uid=0) May 31 14:05:28 musicbox sudo[1846]: pam_unix(sudo:session): session closed for user root May 31 14:05:28 musicbox volumio[976]: info: Installing mpd http output May 31 14:05:28 musicbox volumio[976]: Plugin install end detected on script May 31 14:05:28 musicbox volumio[976]: info: Install script completed May 31 14:05:28 musicbox volumio[976]: info: Adding reference to registry May 31 14:05:28 musicbox volumio[976]: info: Done installing plugin. May 31 14:05:28 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 14:05:28 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 14:05:28 musicbox volumio[976]: info: Folder /tmp/plugins removed May 31 14:05:28 musicbox volumio[976]: info: Folder /tmp/downloaded_plugin.zip removed May 31 14:05:28 musicbox volumio[976]: info: Folder /data/temp removed May 31 14:05:31 musicbox go-librespot[1306]: time="2025-05-31T14:05:31-04:00" level=debug msg="fetched chunk 5/9, size: 524288" uri="spotify:track:2q2Z2A0Mt8AsWyQEdB6wuu" May 31 14:05:31 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:31 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:31 musicbox volumio[976]: info: Listing playlists May 31 14:05:31 musicbox volumio[976]: info: Listing playlists May 31 14:05:34 musicbox volumio[976]: info: Starting Uninstall of plugin audio_interface - mpdoutput May 31 14:05:34 musicbox volumio[976]: info: Uninstalling plugin mpdoutput May 31 14:05:34 musicbox volumio[976]: info: Disabling plugin mpdoutput May 31 14:05:34 musicbox volumio[976]: info: Checking if uninstall.sh is present May 31 14:05:34 musicbox volumio[976]: info: Executing uninstall.sh May 31 14:05:34 musicbox sudo[1853]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/audio_interface/mpdoutput/uninstall.sh May 31 14:05:34 musicbox sudo[1853]: pam_unix(sudo:session): session opened for user root by (uid=0) May 31 14:05:34 musicbox sudo[1853]: pam_unix(sudo:session): session closed for user root May 31 14:05:34 musicbox volumio[976]: info: Uninstall script completed May 31 14:05:34 musicbox volumio[976]: info: Removing plugin mpdoutput from configuration May 31 14:05:34 musicbox volumio[976]: info: Successfully removed mpdoutput configuration files May 31 14:05:34 musicbox volumio[976]: info: Plugin folders cleanup May 31 14:05:34 musicbox volumio[976]: info: Scanning into folder /volumio/app/plugins/ May 31 14:05:34 musicbox volumio[976]: info: Scanning category audio_interface May 31 14:05:34 musicbox volumio[976]: info: Scanning category miscellanea May 31 14:05:34 musicbox volumio[976]: info: Scanning category music_service May 31 14:05:34 musicbox volumio[976]: info: Scanning category plugins.json May 31 14:05:34 musicbox volumio[976]: info: Scanning category system_controller May 31 14:05:34 musicbox volumio[976]: info: Scanning category user_interface May 31 14:05:34 musicbox volumio[976]: info: Scanning into folder /data/plugins/ May 31 14:05:34 musicbox volumio[976]: info: Scanning category audio_interface May 31 14:05:34 musicbox volumio[976]: info: Cleaning folder for mpdoutput May 31 14:05:35 musicbox volumio[976]: info: Scanning category music_service May 31 14:05:35 musicbox volumio[976]: info: Scanning category user_interface May 31 14:05:35 musicbox volumio[976]: info: Plugin folders cleanup completed May 31 14:05:35 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 14:05:35 musicbox volumio[976]: info: [{"prettyName":"Jellyfin","name":"jellyfin","category":"music_service","version":"1.1.1","icon":"fa-music","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"miniDLNA","name":"minidlna","category":"music_service","version":"3.1.12","icon":"fa-share-alt","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Spotify","name":"spop","category":"music_service","version":"4.1.4","icon":"fa-spotify","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Volusonic","name":"volusonic","category":"music_service","version":"2.3.0","icon":"fa-ship","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"YouTube2","name":"youtube2","category":"music_service","version":"1.4.2","icon":"fa-youtube-play","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"YouTube Cast Receiver","name":"ytcr","category":"music_service","version":"1.2.0","icon":"fa-youtube","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"YouTube Music","name":"ytmusic","category":"music_service","version":"1.3.1","icon":"fa-youtube-play","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Now Playing","name":"now_playing","category":"user_interface","version":"0.7.5","icon":"fa-play-circle","isManuallyInstalled":false,"enabled":true,"active":true}] May 31 14:05:35 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 14:05:38 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:38 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:41 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:41 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:44 musicbox go-librespot[1306]: time="2025-05-31T14:05:44-04:00" level=trace msg="sent dealer ping" May 31 14:05:44 musicbox go-librespot[1306]: time="2025-05-31T14:05:44-04:00" level=trace msg="received dealer pong" May 31 14:05:48 musicbox go-librespot[1306]: time="2025-05-31T14:05:48-04:00" level=debug msg="fetched chunk 6/9, size: 524288" uri="spotify:track:2q2Z2A0Mt8AsWyQEdB6wuu" May 31 14:05:51 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:05:51 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:05:51 musicbox volumio[976]: info: Listing playlists May 31 14:05:51 musicbox volumio[976]: info: Listing playlists May 31 14:06:01 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:06:01 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:06:02 musicbox go-librespot[1306]: time="2025-05-31T14:06:02-04:00" level=debug msg="fetched chunk 7/9, size: 524288" uri="spotify:track:2q2Z2A0Mt8AsWyQEdB6wuu" May 31 14:06:06 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 31 14:06:06 musicbox volumio[976]: info: Preload queue cleared May 31 14:06:09 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 31 14:06:09 musicbox volumio[976]: info: Preload queue cleared May 31 14:06:11 musicbox volumio[976]: info: CoreCommandRouter::volumioGetState May 31 14:06:11 musicbox volumio[976]: info: CorePlayQueue::getTrack 0 May 31 14:06:11 musicbox volumio[976]: info: Listing playlists May 31 14:06:11 musicbox volumio[976]: info: Listing playlists May 31 14:06:14 musicbox volumio[976]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri May 31 14:06:14 musicbox volumio[976]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 14:06:14 musicbox volumio[976]: TypeError: Cannot read property 'length' of undefined May 31 14:06:14 musicbox volumio[976]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 May 31 14:06:14 musicbox volumio[976]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 May 31 14:06:14 musicbox volumio[976]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) May 31 14:06:14 musicbox volumio[976]: at Parser.emit (events.js:315:20) May 31 14:06:14 musicbox volumio[976]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) May 31 14:06:14 musicbox volumio[976]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) May 31 14:06:14 musicbox volumio[976]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) May 31 14:06:14 musicbox volumio[976]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) May 31 14:06:14 musicbox volumio[976]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) May 31 14:06:14 musicbox volumio[976]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) May 31 14:06:14 musicbox volumio[976]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) May 31 14:06:14 musicbox volumio[976]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) May 31 14:06:14 musicbox volumio[976]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) May 31 14:06:14 musicbox volumio[976]: at IncomingMessage.emit (events.js:327:22) May 31 14:06:14 musicbox volumio[976]: at endReadableNT (internal/streams/readable.js:1327:12) May 31 14:06:14 musicbox volumio[976]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 31 14:06:14 musicbox volumio[976]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 14:06:14 musicbox go-librespot[1306]: time="2025-05-31T14:06:14-04:00" level=trace msg="sent dealer ping" May 31 14:06:14 musicbox go-librespot[1306]: time="2025-05-31T14:06:14-04:00" level=trace msg="received dealer pong" May 31 14:06:14 musicbox sudo[1973]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-31 14:05 May 31 14:06:14 musicbox sudo[1973]: 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="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"