-- Logs begin at Sat 2024-11-09 04:57:21 AEDT, end at Fri 2024-11-29 12:57:37 AEDT. -- Nov 29 12:56:00 volumio-rpi volumio[4969]: info: Updating MyVolumio device info Nov 29 12:56:00 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 12:56:00 volumio-rpi volumio[4969]: info: [ASDebug] Port: 3 Nov 29 12:56:00 volumio-rpi volumio[4969]: info: [ASDebug] Inverted: false Nov 29 12:56:00 volumio-rpi volumio[4969]: info: [ASDebug] Delay: 0 Nov 29 12:56:01 volumio-rpi volumio[4969]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 29 12:56:02 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:02 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:02 volumio-rpi volumio[4969]: STREAMING PROXY: Starting server on port 3245 Nov 29 12:56:02 volumio-rpi volumio[4969]: Node JS runtime: 14 Nov 29 12:56:03 volumio-rpi volumio[4969]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 29 12:56:05 volumio-rpi volumio[4969]: info: MYVOLUMIO: Adding device Nov 29 12:56:05 volumio-rpi volumio[4969]: info: MYVOLUMIO: Evaluating Server Nov 29 12:56:07 volumio-rpi volumio[4969]: error: MyVolumio Plugin failed to authenticate in a timely fashion Nov 29 12:56:07 volumio-rpi volumio[4969]: info: Completed starting MyVolumio Plugin Nov 29 12:56:07 volumio-rpi volumio[4969]: [Metrics] CommandRouter: 116s 961.86ms Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumiosetStartupVolume Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CoreCommandRouter::Close All Modals sent Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CoreCommandRouter::Close All Modals sent Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:07 volumio-rpi volumio[4969]: info: Setting Geolocation for MyVolumio to au1 Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 12:56:07 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 12:56:07 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:07 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:08 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Nov 29 12:56:08 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 29 12:56:08 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Nov 29 12:56:08 volumio-rpi volumio[4969]: info: Updating MyVolumio device info Nov 29 12:56:08 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 12:56:08 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 12:56:08 volumio-rpi volumio[4969]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 29 12:56:09 volumio-rpi volumio[4969]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 29 12:56:10 volumio-rpi volumio[4969]: info: Enabling plugin gpio_control Nov 29 12:56:10 volumio-rpi volumio[4969]: info: Loading plugin "gpio_control"... Nov 29 12:56:12 volumio-rpi volumio[4969]: gpiox_arm32 V2.1.0 Nov 29 12:56:15 volumio-rpi volumio[4969]: info: Applying required configuration parameters for plugin gpio_control Nov 29 12:56:15 volumio-rpi volumio[4969]: info: PLUGIN START: gpio_control Nov 29 12:56:15 volumio-rpi volumio[4969]: info: [GPIO_Control] Reading config and creating GPIOs Nov 29 12:56:15 volumio-rpi volumio[4969]: info: [GPIO_Control] GPIOs created Nov 29 12:56:15 volumio-rpi volumio[4969]: info: [GPIO_Control] Handling event: systemStartup Nov 29 12:56:15 volumio-rpi volumio[4969]: info: Done. Nov 29 12:56:15 volumio-rpi volumio[4969]: info: BOOT COMPLETED Nov 29 12:56:15 volumio-rpi volumio[4969]: 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 29 12:56:15 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:15 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:15 volumio-rpi volumio[4969]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 29 12:56:16 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:16 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:16 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:16 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:16 volumio-rpi volumio[4969]: info: [GPIO_Control] Status changed: stop Nov 29 12:56:16 volumio-rpi volumio[4969]: info: [GPIO_Control] Handling event: musicStop Nov 29 12:56:16 volumio-rpi volumio[4969]: info: [GPIO_Control] Handling event: repeatAllOff Nov 29 12:56:16 volumio-rpi volumio[4969]: info: [GPIO_Control] Handling event: repeatOff Nov 29 12:56:16 volumio-rpi volumio[4969]: info: [GPIO_Control] Status changed: stop Nov 29 12:56:17 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:17 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:19 volumio-rpi volumio[4969]: info: CALLMETHOD: system_controller system enableLiveLog true Nov 29 12:56:19 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog Nov 29 12:56:19 volumio-rpi volumio[4969]: info: Launching a new LiveLog session Nov 29 12:56:21 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:21 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:26 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:26 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:26 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:26 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:31 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:31 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:31 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:31 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:36 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:36 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:41 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:41 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:46 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:46 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:46 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:46 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:51 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:51 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:56:51 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:51 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:56:56 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:56:56 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:01 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:57:01 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:06 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:57:06 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:06 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:57:06 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:57:10 volumio-rpi volumio[4969]: info: CALLMETHOD: system_hardware gpio_control saveConfig [object Object] Nov 29 12:57:10 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: gpio_control , saveConfig Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] Saving config Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] Reading config and creating GPIOs Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] On musicPlay will set GPIO 3 to On Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] On musicPause will set GPIO 3 to Off Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] On musicStop will set GPIO 3 to Off Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] Handling event: systemStartup Nov 29 12:57:10 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:57:10 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] Status changed: stop Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] Handling event: musicStop Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] *** musicStop *** Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] Handling event: repeatAllOff Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] Handling event: repeatOff Nov 29 12:57:10 volumio-rpi volumio[4969]: info: [GPIO_Control] Turning GPIO 3 Off (musicStop) Nov 29 12:57:11 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:57:11 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:11 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:57:11 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:57:14 volumio-rpi nmbd[557]: [2024/11/29 12:57:14.959919, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Nov 29 12:57:14 volumio-rpi nmbd[557]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.2.213 for name WORKGROUP<1d>. Nov 29 12:57:14 volumio-rpi nmbd[557]: This response was from IP 192.168.1.6, reporting an IP address of 192.168.1.6. Nov 29 12:57:16 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:57:16 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:21 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:57:21 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:26 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioGetState Nov 29 12:57:26 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:26 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:57:26 volumio-rpi volumio[4969]: info: Listing playlists Nov 29 12:57:30 volumio-rpi volumio[4969]: info: Airplay started streaming, receiving metadatas Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioStop Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::stop Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 29 12:57:30 volumio-rpi volumio[4969]: info: Airplay started streaming, receiving metadatas Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioStop Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::stop Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 29 12:57:30 volumio-rpi volumio[4969]: info: Airplay started streaming, receiving metadatas Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioStop Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::stop Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 29 12:57:30 volumio-rpi shairport-sync[5310]: % Total % Received % Xferd Average Speed Time Time Time Current Nov 29 12:57:30 volumio-rpi shairport-sync[5310]: Dload Upload Total Spent Left Speed Nov 29 12:57:30 volumio-rpi volumio[4969]: info: Nov 29 12:57:30 volumio-rpi volumio[4969]: ---------------------------- Client requests Start Airplay PlaybackRoutine Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback Nov 29 12:57:30 volumio-rpi volumio[4969]: info: Airplay playback start Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CorePlayQueue::getTrack 0 Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioStop Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::stop Nov 29 12:57:30 volumio-rpi volumio[4969]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 29 12:57:30 volumio-rpi shairport-sync[5310]: [158B blob data] Nov 29 12:57:31 volumio-rpi volumio[4969]: info: CoreCommandRouter::servicePushState Nov 29 12:57:31 volumio-rpi volumio[4969]: info: CoreStateMachine::pushState Nov 29 12:57:31 volumio-rpi volumio[4969]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 12:57:31 volumio-rpi volumio[4969]: info: CoreCommandRouter::volumioPushState Nov 29 12:57:31 volumio-rpi volumio[4969]: info: [ASDebug] CurState: play PrevState: na Nov 29 12:57:31 volumio-rpi volumio[4969]: info: [ASDebug] Togle GPIO: ON Nov 29 12:57:31 volumio-rpi volumio[4969]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 29 12:57:31 volumio-rpi volumio[4969]: Error: ESPIPE: invalid seek, write Nov 29 12:57:31 volumio-rpi volumio[4969]: at Object.writeSync (fs.js:711:3) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8) Nov 29 12:57:31 volumio-rpi volumio[4969]: at AmpSwitchController.on (/data/plugins/system_controller/ampswitch/index.js:207:23) Nov 29 12:57:31 volumio-rpi volumio[4969]: at AmpSwitchController.parseStatus (/data/plugins/system_controller/ampswitch/index.js:190:86) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Socket.on (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:65:8) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Socket.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Socket.onevent (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/socket.js:278:10) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Socket.onpacket (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/socket.js:236:12) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Manager. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Manager.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Manager.ondecoded (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/manager.js:349:8) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Decoder. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Decoder.Emitter.emit (/data/plugins/system_controller/ampswitch/node_modules/component-emitter/index.js:145:20) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Decoder.add (/data/plugins/system_controller/ampswitch/node_modules/socket.io-parser/index.js:254:12) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Manager.ondata (/data/plugins/system_controller/ampswitch/node_modules/socket.io-client/lib/manager.js:339:16) Nov 29 12:57:31 volumio-rpi volumio[4969]: at Socket. (/data/plugins/system_controller/ampswitch/node_modules/component-bind/index.js:21:15) { Nov 29 12:57:31 volumio-rpi volumio[4969]: errno: -29, Nov 29 12:57:31 volumio-rpi volumio[4969]: syscall: 'write', Nov 29 12:57:31 volumio-rpi volumio[4969]: code: 'ESPIPE' Nov 29 12:57:31 volumio-rpi volumio[4969]: } Nov 29 12:57:31 volumio-rpi volumio[4969]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 29 12:57:37 volumio-rpi sudo[5717]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-29 12:56 Nov 29 12:57:37 volumio-rpi sudo[5717]: 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"