-- Logs begin at Sat 2024-11-02 22:11:20 CET, end at Sat 2024-11-02 22:13:10 CET. -- Nov 02 22:12:00 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 02 22:12:04 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 02 22:12:06 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 02 22:12:06 rpi5-volumio volumio[1179]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Nov 02 22:12:06 rpi5-volumio volumio[1179]: info: CoreCommandRouter::volumioGetState Nov 02 22:12:06 rpi5-volumio volumio[1179]: info: CorePlayQueue::getTrack 0 Nov 02 22:12:06 rpi5-volumio volumio[1179]: info: Enabling MyMusic plugin smart_inputs Nov 02 22:12:06 rpi5-volumio volumio[1179]: info: [MyVolumio PluginManager] Enabling and starting plugin music_service smart_inputs Nov 02 22:12:06 rpi5-volumio volumio[1179]: info: [MyVolumio PluginManager] Plugin music_service smart_inputs not in user plan, not enabling Nov 02 22:12:06 rpi5-volumio volumio[1179]: info: Error: Plugin music_service smart_inputs not in user plan, not enabling Nov 02 22:12:06 rpi5-volumio volumio[1179]: error: Could not Enable MyMusic Plugin: Error Nov 02 22:12:08 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::volumioGetBrowseSources Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 02 22:12:11 rpi5-volumio volumio[1179]: error: MyVolumio Plugin failed to authenticate in a timely fashion Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: Completed starting MyVolumio Plugin Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: BOOT COMPLETED Nov 02 22:12:11 rpi5-volumio volumio[1179]: [Metrics] CommandRouter: 32s 391.14ms Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::volumiosetStartupVolume Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::Close All Modals sent Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::Close All Modals sent Nov 02 22:12:11 rpi5-volumio volumio-remote-updater[815]: No test mode Nov 02 22:12:11 rpi5-volumio volumio-remote-updater[815]: No alpha test mode Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Nov 02 22:12:11 rpi5-volumio kernel: voicehat-codec voicehat-codec: Enabling audio amp... Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Nov 02 22:12:11 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Nov 02 22:12:12 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Nov 02 22:12:12 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 02 22:12:12 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Nov 02 22:12:12 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 02 22:12:16 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 02 22:12:17 rpi5-volumio kernel: voicehat-codec voicehat-codec: Disabling audio amp... Nov 02 22:12:20 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Nov 02 22:12:21 rpi5-volumio volumio[1179]: info: CoreCommandRouter::volumioGetQueue Nov 02 22:12:21 rpi5-volumio volumio[1179]: info: CoreStateMachine::getQueue Nov 02 22:12:21 rpi5-volumio volumio[1179]: info: CorePlayQueue::getQueue Nov 02 22:12:21 rpi5-volumio volumio[1179]: info: Preload queue cleared Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: Getting Alsa Cards List without I2S DAC Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Nov 02 22:12:24 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Nov 02 22:12:30 rpi5-volumio ntpd[1005]: Soliciting pool server 193.99.165.216 Nov 02 22:12:30 rpi5-volumio ntpd[1005]: Soliciting pool server 194.50.19.117 Nov 02 22:12:31 rpi5-volumio ntpd[1005]: Soliciting pool server 129.70.132.33 Nov 02 22:12:31 rpi5-volumio ntpd[1005]: Soliciting pool server 188.245.32.133 Nov 02 22:12:32 rpi5-volumio ntpd[1005]: Soliciting pool server 167.71.55.144 Nov 02 22:12:32 rpi5-volumio ntpd[1005]: Soliciting pool server 178.63.52.31 Nov 02 22:12:32 rpi5-volumio ntpd[1005]: Soliciting pool server 213.172.105.106 Nov 02 22:12:33 rpi5-volumio ntpd[1005]: Soliciting pool server 85.215.189.120 Nov 02 22:12:33 rpi5-volumio ntpd[1005]: Soliciting pool server 129.70.132.35 Nov 02 22:12:33 rpi5-volumio ntpd[1005]: Soliciting pool server 88.198.7.62 Nov 02 22:12:34 rpi5-volumio ntpd[1005]: Soliciting pool server 2a01:4f8:201:3383::2 Nov 02 22:12:34 rpi5-volumio ntpd[1005]: Soliciting pool server 141.82.25.202 Nov 02 22:12:34 rpi5-volumio ntpd[1005]: Soliciting pool server 185.232.69.65 Nov 02 22:12:35 rpi5-volumio ntpd[1005]: Soliciting pool server 144.76.59.37 Nov 02 22:12:35 rpi5-volumio ntpd[1005]: Soliciting pool server 116.202.171.176 Nov 02 22:12:36 rpi5-volumio ntpd[1005]: Soliciting pool server 17.253.14.251 Nov 02 22:12:37 rpi5-volumio ntpd[1005]: Soliciting pool server 90.187.112.137 Nov 02 22:12:37 rpi5-volumio ntpd[1005]: receive: Unexpected origin timestamp 0xead11445.81bd8d2f does not match aorg 0000000000.00000000 from server@188.245.32.133 xmt 0xead11445.ad329604 Nov 02 22:12:37 rpi5-volumio ntpd[1005]: receive: Unexpected origin timestamp 0xead11445.81bcdd3f does not match aorg 0000000000.00000000 from server@129.70.132.33 xmt 0xead11445.ad9f02a9 Nov 02 22:12:37 rpi5-volumio ntpd[1005]: receive: Unexpected origin timestamp 0xead11445.81baa9b6 does not match aorg 0000000000.00000000 from server@129.70.132.35 xmt 0xead11445.adaf39c3 Nov 02 22:12:37 rpi5-volumio ntpd[1005]: receive: Unexpected origin timestamp 0xead11445.81b9c2f0 does not match aorg 0000000000.00000000 from server@85.215.189.120 xmt 0xead11445.add654d2 Nov 02 22:12:37 rpi5-volumio ntpd[1005]: receive: Unexpected origin timestamp 0xead11445.81b7ee6e does not match aorg 0000000000.00000000 from server@141.82.25.202 xmt 0xead11445.adf8f48f Nov 02 22:12:42 rpi5-volumio volumio[1179]: info: CoreCommandRouter::volumioPlay Nov 02 22:12:42 rpi5-volumio volumio[1179]: info: CoreStateMachine::play index undefined Nov 02 22:12:42 rpi5-volumio volumio[1179]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 02 22:12:42 rpi5-volumio volumio[1179]: info: CorePlayQueue::getTrack 0 Nov 02 22:12:46 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 02 22:12:46 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Nov 02 22:12:50 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: last_100 , handleBrowseUri Nov 02 22:12:51 rpi5-volumio volumio[1179]: Error Retrieving last played file: Error: /data/laststates.json: ENOENT: no such file or directory, open '/data/laststates.json' Nov 02 22:12:51 rpi5-volumio volumio[1179]: info: Preload queue cleared Nov 02 22:13:01 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 02 22:13:01 rpi5-volumio volumio[1179]: info: Preload queue cleared Nov 02 22:13:05 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 02 22:13:05 rpi5-volumio volumio[1179]: info: Preload queue cleared Nov 02 22:13:06 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 02 22:13:07 rpi5-volumio volumio[1179]: info: Preload queue cleared Nov 02 22:13:10 rpi5-volumio volumio[1179]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Nov 02 22:13:10 rpi5-volumio volumio[1179]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 02 22:13:10 rpi5-volumio volumio[1179]: TypeError: Cannot read property 'length' of undefined Nov 02 22:13:10 rpi5-volumio volumio[1179]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Nov 02 22:13:10 rpi5-volumio volumio[1179]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Nov 02 22:13:10 rpi5-volumio volumio[1179]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at Parser.emit (events.js:315:20) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at IncomingMessage.emit (events.js:327:22) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at endReadableNT (internal/streams/readable.js:1327:12) Nov 02 22:13:10 rpi5-volumio volumio[1179]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Nov 02 22:13:10 rpi5-volumio volumio[1179]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 02 22:13:10 rpi5-volumio sudo[1558]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-02 22:12 Nov 02 22:13:10 rpi5-volumio sudo[1558]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"