-- Logs begin at Wed 2024-02-21 15:42:47 EST, end at Mon 2024-05-06 16:43:58 EDT. --
May 06 16:42:00 room1 volumio-remote-updater[550]: PROGRESS: 28, STATUS: "Creating backup", ETA: "5m"
May 06 16:42:00 room1 volumio-remote-updater[550]: PROGRESS: 29, STATUS: "Creating backup", ETA: "5m"
May 06 16:42:00 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:42:00 room1 volumio[908]: updateProgress
May 06 16:42:00 room1 volumio[908]: {
May 06 16:42:00 room1 volumio[908]: downloadSpeed: '',
May 06 16:42:00 room1 volumio[908]: eta: '5m',
May 06 16:42:00 room1 volumio[908]: progress: 29,
May 06 16:42:00 room1 volumio[908]: status: 'Creating backup'
May 06 16:42:00 room1 volumio[908]: }
May 06 16:42:00 room1 volumio-remote-updater[550]: PROGRESS: 29, STATUS: "Creating backup", ETA: "5m"
May 06 16:42:00 room1 volumio-remote-updater[550]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m"
May 06 16:42:00 room1 volumio-remote-updater[550]: PROGRESS: 30, STATUS: "Creating backup", ETA: "5m"
May 06 16:42:00 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:42:00 room1 volumio[908]: updateProgress
May 06 16:42:00 room1 volumio[908]: {
May 06 16:42:00 room1 volumio[908]: downloadSpeed: '',
May 06 16:42:00 room1 volumio[908]: eta: '5m',
May 06 16:42:00 room1 volumio[908]: progress: 30,
May 06 16:42:00 room1 volumio[908]: status: 'Creating backup'
May 06 16:42:00 room1 volumio[908]: }
May 06 16:42:00 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:42:00 room1 volumio[908]: updateProgress
May 06 16:42:00 room1 volumio[908]: {
May 06 16:42:00 room1 volumio[908]: downloadSpeed: '',
May 06 16:42:00 room1 volumio[908]: eta: '5m',
May 06 16:42:00 room1 volumio[908]: progress: 30,
May 06 16:42:00 room1 volumio[908]: status: 'Creating backup'
May 06 16:42:00 room1 volumio[908]: }
May 06 16:42:02 room1 volumio-remote-updater[550]: PROGRESS: 30, STATUS: "Downloading new update", ETA: "4m"
May 06 16:42:02 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:42:02 room1 volumio[908]: updateProgress
May 06 16:42:02 room1 volumio[908]: {
May 06 16:42:02 room1 volumio[908]: downloadSpeed: '',
May 06 16:42:02 room1 volumio[908]: eta: '4m',
May 06 16:42:02 room1 volumio[908]: progress: 30,
May 06 16:42:02 room1 volumio[908]: status: 'Downloading new update'
May 06 16:42:02 room1 volumio[908]: }
May 06 16:42:27 room1 volumio[908]: info: CorePlayQueue::getTrack 12
May 06 16:42:27 room1 volumio[908]: info: CorePlayQueue::getTrack 13
May 06 16:42:27 room1 volumio[908]: info: Prefetching next song
May 06 16:42:27 room1 volumio[908]: info: [1715028147218] ControllerTidal::prefetch
May 06 16:42:27 room1 volumio[908]: info: Getting stream with soundQuality LOSSLESS
May 06 16:42:27 room1 volumio[908]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/354687460&soundQuality=LOSSLESS"
May 06 16:42:27 room1 volumio[908]: info:
May 06 16:42:27 room1 volumio[908]: ---------------------------- MPD announces system playlist update
May 06 16:42:27 room1 volumio[908]: info: Ignoring MPD Status Update
May 06 16:42:27 room1 volumio[908]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/354687460&soundQuality=LOSSLESS" took 1 milliseconds
May 06 16:42:27 room1 volumio[908]: info: CoreStateMachine::setConsumeUpdateService mpd
May 06 16:42:27 room1 volumio[908]: verbose: ControllerMpd::sendMpdCommand consume 1
May 06 16:42:27 room1 volumio[908]: info: ------------------------------ 3ms
May 06 16:42:27 room1 volumio[908]: info: sendMpdCommand consume 1 took 1 milliseconds
May 06 16:42:31 room1 volumio[908]: info: CoreStateMachine::startPlaybackTimer
May 06 16:42:31 room1 volumio[908]: info: CorePlayQueue::getTrack 13
May 06 16:42:32 room1 volumio[908]: info: CoreStateMachine::pushState
May 06 16:42:32 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 06 16:42:32 room1 volumio[908]: info: CoreCommandRouter::volumioPushState
May 06 16:42:32 room1 volumio[908]: info: MRS: Pushing multiroomSync output update for this device
May 06 16:42:32 room1 volumio[908]: info: MRS: Pushing multiroomSync output
May 06 16:42:32 room1 volumio[908]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
May 06 16:43:25 room1 volumio-remote-updater[550]: zsync done
May 06 16:43:25 room1 systemd[1]: Starting Cleanup of Temporary Directories...
May 06 16:43:25 room1 volumio[908]: ------------------------------------ BT MESSAGE: BT STATUS: running
May 06 16:43:25 room1 volumio-remote-updater[550]: PROGRESS: 80, STATUS: "Downloading new update", ETA: "2m"
May 06 16:43:25 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:25 room1 volumio[908]: updateProgress
May 06 16:43:25 room1 volumio[908]: {
May 06 16:43:25 room1 volumio[908]: downloadSpeed: '',
May 06 16:43:25 room1 volumio[908]: eta: '2m',
May 06 16:43:25 room1 volumio[908]: progress: 80,
May 06 16:43:25 room1 volumio[908]: status: 'Downloading new update'
May 06 16:43:25 room1 volumio[908]: }
May 06 16:43:25 room1 systemd[1]: systemd-tmpfiles-clean.service: Succeeded.
May 06 16:43:25 room1 systemd[1]: Started Cleanup of Temporary Directories.
May 06 16:43:26 room1 volumio[908]: info: CorePlayQueue::getTrack 13
May 06 16:43:26 room1 volumio[908]: info: CorePlayQueue::getTrack 14
May 06 16:43:26 room1 volumio[908]: info: Prefetching next song
May 06 16:43:26 room1 volumio[908]: info: [1715028206795] ControllerTidal::prefetch
May 06 16:43:26 room1 volumio[908]: info: Getting stream with soundQuality LOSSLESS
May 06 16:43:26 room1 volumio[908]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/354687461&soundQuality=LOSSLESS"
May 06 16:43:26 room1 volumio[908]: info:
May 06 16:43:26 room1 volumio[908]: ---------------------------- MPD announces system playlist update
May 06 16:43:26 room1 volumio[908]: info: Ignoring MPD Status Update
May 06 16:43:26 room1 volumio[908]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/354687461&soundQuality=LOSSLESS" took 1 milliseconds
May 06 16:43:26 room1 volumio[908]: info: CoreStateMachine::setConsumeUpdateService mpd
May 06 16:43:26 room1 volumio[908]: verbose: ControllerMpd::sendMpdCommand consume 1
May 06 16:43:26 room1 volumio[908]: info: ------------------------------ 2ms
May 06 16:43:26 room1 volumio[908]: info: sendMpdCommand consume 1 took 1 milliseconds
May 06 16:43:31 room1 volumio[908]: info: CoreStateMachine::startPlaybackTimer
May 06 16:43:31 room1 volumio[908]: info: CorePlayQueue::getTrack 14
May 06 16:43:31 room1 volumio[908]: info: CoreStateMachine::pushState
May 06 16:43:31 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 06 16:43:31 room1 volumio[908]: info: CoreCommandRouter::volumioPushState
May 06 16:43:31 room1 volumio[908]: info: MRS: Pushing multiroomSync output update for this device
May 06 16:43:31 room1 volumio[908]: info: MRS: Pushing multiroomSync output
May 06 16:43:31 room1 volumio[908]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100
May 06 16:43:36 room1 volumio[908]: info: Tunnel connection is inactive, restarting it
May 06 16:43:36 room1 volumio[908]: info: Starting Tunnel 1
May 06 16:43:36 room1 volumio[908]: info: Starting Tunnel Connection Checker
May 06 16:43:40 room1 volumio-remote-updater[550]: zsync done
May 06 16:43:41 room1 volumio-remote-updater[550]: PROGRESS: 90, STATUS: "Cleaning old files", ETA: "1m"
May 06 16:43:41 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:41 room1 volumio[908]: updateProgress
May 06 16:43:41 room1 volumio[908]: {
May 06 16:43:41 room1 volumio[908]: downloadSpeed: '',
May 06 16:43:41 room1 volumio[908]: eta: '1m',
May 06 16:43:41 room1 volumio[908]: progress: 90,
May 06 16:43:41 room1 volumio[908]: status: 'Cleaning old files'
May 06 16:43:41 room1 volumio[908]: }
May 06 16:43:41 room1 volumio-remote-updater[550]: /bin/cp: cannot stat '/data/volumio_factory.sqsh': No such file or directory
May 06 16:43:41 room1 sudo[3090]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service
May 06 16:43:41 room1 sudo[3090]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 06 16:43:41 room1 volumio-remote-updater[550]: /bin/rm: cannot remove '/data/volumio_factory.sqsh': No such file or directory
May 06 16:43:41 room1 volumio-remote-updater[550]: PROGRESS: 95, STATUS: "Finalizing update", ETA: "30s"
May 06 16:43:41 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:41 room1 volumio[908]: updateProgress
May 06 16:43:41 room1 volumio[908]: {
May 06 16:43:41 room1 volumio[908]: downloadSpeed: '',
May 06 16:43:41 room1 volumio[908]: eta: '30s',
May 06 16:43:41 room1 volumio[908]: progress: 95,
May 06 16:43:41 room1 volumio[908]: status: 'Finalizing update'
May 06 16:43:41 room1 volumio[908]: }
May 06 16:43:41 room1 autossh[2842]: received signal to exit (15)
May 06 16:43:41 room1 systemd[1]: Stopping MyVolumio SSH Tunnel...
May 06 16:43:41 room1 systemd[1]: sshtunnel.service: Main process exited, code=killed, status=15/TERM
May 06 16:43:41 room1 volumio[908]: ------------------------------------ BT MESSAGE: BT STATUS: running
May 06 16:43:41 room1 systemd[1]: sshtunnel.service: Succeeded.
May 06 16:43:41 room1 systemd[1]: Stopped MyVolumio SSH Tunnel.
May 06 16:43:41 room1 volumio[908]: ------------------------------------ BT MESSAGE: BT STATUS: waiting
May 06 16:43:41 room1 systemd[1]: Started MyVolumio SSH Tunnel.
May 06 16:43:41 room1 sudo[3090]: pam_unix(sudo:session): session closed for user root
May 06 16:43:41 room1 volumio[908]: info: Remote SSH Started
May 06 16:43:41 room1 autossh[3103]: port set to 0, monitoring disabled
May 06 16:43:41 room1 autossh[3103]: starting ssh (count 1)
May 06 16:43:41 room1 volumio[908]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12
May 06 16:43:41 room1 autossh[3103]: ssh child pid is 3106
May 06 16:43:41 room1 volumio[908]: info: CoreCommandRouter::volumioGetState
May 06 16:43:41 room1 volumio[908]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.NR9lbKX3ojWaPZbv4WCTAGhhJY73.d786c1d25c0a0e56c19f25a2721c4743.state.status'
May 06 16:43:42 room1 volumio-remote-updater[550]: PROGRESS: 100, STATUS: "success", MESSAGE: "Successfully updated to \"3.661\" version. System restart required."
May 06 16:43:42 room1 volumio-remote-updater[550]: No test mode
May 06 16:43:42 room1 volumio-remote-updater[550]: No alpha test mode
May 06 16:43:42 room1 volumiossh-tunnel[3102]: Warning: Permanently added '[us1.myvolumio.org]:2222,[162.243.167.188]:2222' (RSA) to the list of known hosts.
May 06 16:43:42 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:42 room1 volumio-remote-updater[550]: [2024-05-06 16:43:42] [disconnect] Disconnect close local:[1000] remote:[1000]
May 06 16:43:42 room1 volumio-remote-updater[550]: [2024-05-06 16:43:42] [info] asio async_write error: system:32 (Broken pipe)
May 06 16:43:42 room1 volumio-remote-updater[550]: [2024-05-06 16:43:42] [fatal] handle_write_frame error: websocketpp.transport:2 (Underlying Transport Error)
May 06 16:43:42 room1 volumio[908]: updateReady
May 06 16:43:42 room1 volumio[908]: {
May 06 16:43:42 room1 volumio[908]: changeLogLink: 'http://volumio.org',
May 06 16:43:42 room1 volumio[908]: description: 'FIXES
- Fix for mpd crashing with wrongly formatted cue files
- Restore install-to-disk on x86 and ThinkerBoard
- Fix for Waveshare 11.9inch DSI Display touch panel on RPi
- Fix for missing metadata on CD playback
- Fix for metadata with Classic and Modern UI
- Fix for factory-reset from USB on Motivo
- Fix for Volumio logo on boot on Motivo
- Various fixes for TIDAL Connect
- Fix japanese and thai characters on HDMI display
- Fix for keyboard opening on select on mobile
NEW ADDITIONS
- Add filtering to QOBUZ New releases
- Bump MPD to 0.23.15-3
- Add support for Waveshare 4.0inch DSI Display on RPi
- Improvements for reducing boot time
- Add patched driver for ax88179 on RPi
',
May 06 16:43:42 room1 volumio[908]: title: 'Update v3.661',
May 06 16:43:42 room1 volumio[908]: updateavailable: true
May 06 16:43:42 room1 volumio[908]: }
May 06 16:43:42 room1 systemd[1]: volumio-remote-updater.service: Succeeded.
May 06 16:43:42 room1 systemd[1]: volumio-remote-updater.service: Service RestartSec=100ms expired, scheduling restart.
May 06 16:43:42 room1 systemd[1]: volumio-remote-updater.service: Scheduled restart job, restart counter is at 1.
May 06 16:43:42 room1 systemd[1]: Stopped volumio-remote-updater.service.
May 06 16:43:42 room1 systemd[1]: Started volumio-remote-updater.service.
May 06 16:43:42 room1 volumio-remote-updater[3109]: Error: No active session
May 06 16:43:42 room1 volumio-remote-updater[3109]: [2024-05-06 16:43:42] [connect] Successful connection
May 06 16:43:42 room1 volumio-remote-updater[3109]: [2024-05-06 16:43:42] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1715028222 101
May 06 16:43:42 room1 volumio[908]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 12
May 06 16:43:43 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:44 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:45 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:46 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:47 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:48 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:49 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:50 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:51 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:52 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:53 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:54 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:55 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:56 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:57 room1 volumio[908]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage
May 06 16:43:58 room1 volumio[908]: info: CoreCommandRouter::Close All Modals sent
May 06 16:43:58 room1 volumio[908]: info: ___________ PLUGINS: Run onVolumioReboot Tasks ___________
May 06 16:43:58 room1 volumio[908]: info: PLUGIN onReboot : networkfs
May 06 16:43:58 room1 volumio[908]: info: PLUGIN onReboot : audiophonicsonoff
May 06 16:43:58 room1 volumio[908]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
May 06 16:43:58 room1 volumio[908]: TypeError: Cannot read property 'writeSync' of undefined
May 06 16:43:58 room1 volumio[908]: at ControllerAudiophonicsOnOff.onVolumioReboot (/data/plugins/system_controller/audiophonicsonoff/index.js:35:25)
May 06 16:43:58 room1 volumio[908]: at PluginManager.onVolumioRebootPlugin (/volumio/app/pluginmanager.js:684:30)
May 06 16:43:58 room1 volumio[908]: at HashMap. (/volumio/app/pluginmanager.js:668:31)
May 06 16:43:58 room1 volumio[908]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10)
May 06 16:43:58 room1 volumio[908]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7)
May 06 16:43:58 room1 volumio[908]: at PluginManager.onVolumioReboot (/volumio/app/pluginmanager.js:666:20)
May 06 16:43:58 room1 volumio[908]: at CoreCommandRouter.reboot (/volumio/app/index.js:1325:22)
May 06 16:43:58 room1 volumio[908]: at Timeout._onTimeout (/volumio/app/plugins/system_controller/updater_comm/index.js:156:35)
May 06 16:43:58 room1 volumio[908]: at listOnTimeout (internal/timers.js:554:17)
May 06 16:43:58 room1 volumio[908]: at processTimers (internal/timers.js:497:7)
May 06 16:43:58 room1 volumio[908]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
May 06 16:43:58 room1 sudo[3121]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-06 16:42
May 06 16:43:58 room1 sudo[3121]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d"
VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71"
VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1"
VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET"
VOLUMIO_VERSION="3.631"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"