-- Logs begin at Thu 2025-02-13 15:20:08 CET, end at Fri 2025-02-14 19:58:48 CET. -- Feb 14 19:57:00 tirion go-librespot[29745]: time="2025-02-14T19:57:00+01:00" level=debug msg="fetched chunk 7/12, size: 524288" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:57:08 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:08 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:08 tirion volumio[975]: info: Listing playlists Feb 14 19:57:08 tirion volumio[975]: info: Listing playlists Feb 14 19:57:08 tirion volumio[975]: info: Listing playlists Feb 14 19:57:14 tirion go-librespot[29745]: time="2025-02-14T19:57:14+01:00" level=debug msg="fetched chunk 8/12, size: 524288" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:57:18 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:18 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:28 tirion go-librespot[29745]: time="2025-02-14T19:57:28+01:00" level=debug msg="fetched chunk 9/12, size: 524288" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:57:28 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:28 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:28 tirion volumio[975]: info: Listing playlists Feb 14 19:57:28 tirion volumio[975]: info: Listing playlists Feb 14 19:57:28 tirion volumio[975]: info: Listing playlists Feb 14 19:57:28 tirion volumio[975]: info: Listing playlists Feb 14 19:57:38 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:38 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:40 tirion go-librespot[29745]: time="2025-02-14T19:57:40+01:00" level=debug msg="fetched chunk 10/12, size: 524288" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:57:43 tirion volumio-remote-updater[607]: zsync done Feb 14 19:57:43 tirion volumio-remote-updater[607]: PROGRESS: 80, STATUS: "Downloading new update", ETA: "2m" Feb 14 19:57:43 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:57:43 tirion volumio[975]: updateProgress Feb 14 19:57:43 tirion volumio[975]: { Feb 14 19:57:43 tirion volumio[975]: downloadSpeed: '', Feb 14 19:57:43 tirion volumio[975]: eta: '2m', Feb 14 19:57:43 tirion volumio[975]: progress: 80, Feb 14 19:57:43 tirion volumio[975]: status: 'Neue Aktualisierung wird heruntergeladen' Feb 14 19:57:43 tirion volumio[975]: } Feb 14 19:57:48 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:48 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:48 tirion volumio[975]: info: Listing playlists Feb 14 19:57:48 tirion volumio[975]: info: Listing playlists Feb 14 19:57:48 tirion volumio[975]: info: Listing playlists Feb 14 19:57:48 tirion volumio[975]: info: Listing playlists Feb 14 19:57:58 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:57:58 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:02 tirion go-librespot[29745]: time="2025-02-14T19:58:02+01:00" level=debug msg="fetched chunk 11/12, size: 524288" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:58:05 tirion go-librespot[29745]: time="2025-02-14T19:58:05+01:00" level=debug msg="fetched chunk 12/12, size: 475591" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:58:08 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:08 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:08 tirion volumio[975]: info: Listing playlists Feb 14 19:58:08 tirion volumio[975]: info: Listing playlists Feb 14 19:58:08 tirion volumio[975]: info: Listing playlists Feb 14 19:58:10 tirion go-librespot[29745]: time="2025-02-14T19:58:10+01:00" level=debug msg="handling transfer player command from 1b2f1bffebe7c94bfbf497a58a420f7fd2557cbd" Feb 14 19:58:10 tirion go-librespot[29745]: time="2025-02-14T19:58:10+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EIUs5prqXk3Iy" Feb 14 19:58:10 tirion go-librespot[29745]: time="2025-02-14T19:58:10+01:00" level=trace msg="fetched new page 0 with 35 items (list: 35)" uri="spotify:playlist:37i9dQZF1EIUs5prqXk3Iy" Feb 14 19:58:10 tirion go-librespot[29745]: time="2025-02-14T19:58:10+01:00" level=debug msg="loading track (paused: false, position: 124157ms)" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:58:10 tirion go-librespot[29745]: time="2025-02-14T19:58:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 14 19:58:10 tirion go-librespot[29745]: time="2025-02-14T19:58:10+01:00" level=trace msg="emitting websocket event: will_play" Feb 14 19:58:10 tirion volumio[975]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2K4sWGg916F0BTISnG1iXU","play_origin":"playlist/ondemand"}} Feb 14 19:58:10 tirion go-librespot[29745]: time="2025-02-14T19:58:10+01:00" level=debug msg="selected format OGG_VORBIS_320 (3ac327d698262a42680342dc2a4c71e42f1a7af4)" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:58:10 tirion go-librespot[29745]: time="2025-02-14T19:58:10+01:00" level=debug msg="requested aes key for file 3ac327d698262a42680342dc2a4c71e42f1a7af4, gid: 2K4sWGg916F0BTISnG1iXU" Feb 14 19:58:14 tirion go-librespot[29745]: time="2025-02-14T19:58:14+01:00" level=debug msg="fetched first chunk of 13, total size is 6767047 bytes" uri="spotify:track:2K4sWGg916F0BTISnG1iXU" Feb 14 19:58:18 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:18 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:25 tirion go-librespot[29745]: time="2025-02-14T19:58:25+01:00" level=debug msg="prefetching next track" uri="spotify:track:0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:25 tirion go-librespot[29745]: time="2025-02-14T19:58:25+01:00" level=debug msg="selected format OGG_VORBIS_320 (25a93e9552b5003b7eb72e01a8c9e19b181a5f41)" uri="spotify:track:0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:25 tirion go-librespot[29745]: time="2025-02-14T19:58:25+01:00" level=debug msg="requested aes key for file 25a93e9552b5003b7eb72e01a8c9e19b181a5f41, gid: 0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:26 tirion go-librespot[29745]: time="2025-02-14T19:58:26+01:00" level=debug msg="fetched first chunk of 17, total size is 8542824 bytes" uri="spotify:track:0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:26 tirion go-librespot[29745]: time="2025-02-14T19:58:26+01:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:26 tirion go-librespot[29745]: time="2025-02-14T19:58:26+01:00" level=info msg="prefetched track \"Invictus\" (duration: 204812ms)" uri="spotify:track:0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:26 tirion go-librespot[29745]: time="2025-02-14T19:58:26+01:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:26 tirion go-librespot[29745]: time="2025-02-14T19:58:26+01:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:26 tirion go-librespot[29745]: time="2025-02-14T19:58:26+01:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:0ASPbAzGNzWSuUJYMpM4YY" Feb 14 19:58:27 tirion volumio-remote-updater[607]: zsync done Feb 14 19:58:27 tirion volumio-remote-updater[607]: PROGRESS: 90, STATUS: "Cleaning old files", ETA: "1m" Feb 14 19:58:27 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:27 tirion volumio[975]: updateProgress Feb 14 19:58:27 tirion volumio[975]: { Feb 14 19:58:27 tirion volumio[975]: downloadSpeed: '', Feb 14 19:58:27 tirion volumio[975]: eta: '1m', Feb 14 19:58:27 tirion volumio[975]: progress: 90, Feb 14 19:58:27 tirion volumio[975]: status: 'Alte Dateien werden bereinigt' Feb 14 19:58:27 tirion volumio[975]: } Feb 14 19:58:27 tirion volumio-remote-updater[607]: /bin/cp: cannot stat '/data/volumio_factory.sqsh': No such file or directory Feb 14 19:58:27 tirion volumio-remote-updater[607]: /bin/rm: cannot remove '/data/volumio_factory.sqsh': No such file or directory Feb 14 19:58:27 tirion volumio-remote-updater[607]: PROGRESS: 95, STATUS: "Finalizing update", ETA: "30s" Feb 14 19:58:27 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:27 tirion volumio[975]: updateProgress Feb 14 19:58:27 tirion volumio[975]: { Feb 14 19:58:27 tirion volumio[975]: downloadSpeed: '', Feb 14 19:58:27 tirion volumio[975]: eta: '30s', Feb 14 19:58:27 tirion volumio[975]: progress: 95, Feb 14 19:58:27 tirion volumio[975]: status: 'Aktualisierung wird abgeschlossen' Feb 14 19:58:27 tirion volumio[975]: } Feb 14 19:58:28 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:28 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:28 tirion volumio[975]: info: Listing playlists Feb 14 19:58:28 tirion volumio[975]: info: Listing playlists Feb 14 19:58:28 tirion volumio-remote-updater[607]: PROGRESS: 100, STATUS: "success", MESSAGE: "Successfully updated to \"3.785\" version. System restart required." Feb 14 19:58:28 tirion volumio-remote-updater[607]: No test mode Feb 14 19:58:28 tirion volumio-remote-updater[607]: No alpha test mode Feb 14 19:58:28 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:28 tirion volumio[975]: updateReady Feb 14 19:58:28 tirion volumio[975]: { Feb 14 19:58:28 tirion volumio[975]: changeLogLink: 'http://volumio.org', Feb 14 19:58:28 tirion volumio[975]: description: '

FIXES

 

NEW ADDITIONS

 

', Feb 14 19:58:28 tirion volumio[975]: title: 'Update v3.785', Feb 14 19:58:28 tirion volumio[975]: updateavailable: true Feb 14 19:58:28 tirion volumio[975]: } Feb 14 19:58:28 tirion volumio-remote-updater[607]: [2025-02-14 19:58:28] [disconnect] Disconnect close local:[1000] remote:[1000] Feb 14 19:58:29 tirion volumio-remote-updater[607]: [2025-02-14 19:58:29] [info] asio async_write error: system:32 (Broken pipe) Feb 14 19:58:29 tirion volumio-remote-updater[607]: [2025-02-14 19:58:29] [fatal] handle_write_frame error: websocketpp.transport:2 (Underlying Transport Error) Feb 14 19:58:29 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:30 tirion systemd[1]: volumio-remote-updater.service: Succeeded. Feb 14 19:58:30 tirion systemd[1]: volumio-remote-updater.service: Service RestartSec=100ms expired, scheduling restart. Feb 14 19:58:30 tirion systemd[1]: volumio-remote-updater.service: Scheduled restart job, restart counter is at 1. Feb 14 19:58:30 tirion systemd[1]: Stopped volumio-remote-updater.service. Feb 14 19:58:30 tirion systemd[1]: Started volumio-remote-updater.service. Feb 14 19:58:30 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:30 tirion volumio-remote-updater[12934]: Error: No active session Feb 14 19:58:30 tirion volumio-remote-updater[12934]: [2025-02-14 19:58:30] [connect] Successful connection Feb 14 19:58:30 tirion volumio-remote-updater[12934]: [2025-02-14 19:58:30] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1739559510 101 Feb 14 19:58:31 tirion volumio[975]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 6 Feb 14 19:58:31 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:32 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:33 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:34 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:35 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:36 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:37 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:37 tirion kernel: hwmon hwmon1: Voltage normalised Feb 14 19:58:38 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:38 tirion volumio[975]: info: CoreCommandRouter::volumioGetState Feb 14 19:58:38 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:39 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:40 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:41 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:42 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:43 tirion go-librespot[29745]: time="2025-02-14T19:58:43+01:00" level=error msg="did not receive last pong from dealer, 60s passed" Feb 14 19:58:43 tirion volumio[975]: info: CoreCommandRouter::executeOnPlugin: websocket , broadcastMessage Feb 14 19:58:44 tirion volumio[975]: info: CoreCommandRouter::Close All Modals sent Feb 14 19:58:44 tirion volumio[975]: info: ___________ PLUGINS: Run onVolumioReboot Tasks ___________ Feb 14 19:58:44 tirion volumio[975]: info: PLUGIN onReboot : networkfs Feb 14 19:58:44 tirion sudo[12989]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount -f /mnt/NAS/Music Feb 14 19:58:44 tirion sudo[12989]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 14 19:58:44 tirion sudo[12989]: pam_unix(sudo:session): session closed for user root Feb 14 19:58:44 tirion systemd[1]: mnt-NAS-Music.mount: Succeeded. Feb 14 19:58:45 tirion sudo[12993]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount -f /mnt/NAS/Audiobooks Feb 14 19:58:45 tirion sudo[12993]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 14 19:58:45 tirion systemd[1]: mnt-NAS-Audiobooks.mount: Succeeded. Feb 14 19:58:45 tirion sudo[12993]: pam_unix(sudo:session): session closed for user root Feb 14 19:58:45 tirion volumio[975]: info: PLUGIN onReboot : audiophonicsonoff Feb 14 19:58:45 tirion volumio[975]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 14 19:58:45 tirion volumio[975]: TypeError: Cannot read property 'writeSync' of undefined Feb 14 19:58:45 tirion volumio[975]: at ControllerAudiophonicsOnOff.onVolumioReboot (/data/plugins/system_controller/audiophonicsonoff/index.js:35:25) Feb 14 19:58:45 tirion volumio[975]: at PluginManager.onVolumioRebootPlugin (/volumio/app/pluginmanager.js:684:30) Feb 14 19:58:45 tirion volumio[975]: at HashMap. (/volumio/app/pluginmanager.js:668:31) Feb 14 19:58:45 tirion volumio[975]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Feb 14 19:58:45 tirion volumio[975]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Feb 14 19:58:45 tirion volumio[975]: at PluginManager.onVolumioReboot (/volumio/app/pluginmanager.js:666:20) Feb 14 19:58:45 tirion volumio[975]: at CoreCommandRouter.reboot (/volumio/app/index.js:1345:22) Feb 14 19:58:45 tirion volumio[975]: at Timeout._onTimeout (/volumio/app/plugins/system_controller/updater_comm/index.js:156:35) Feb 14 19:58:45 tirion volumio[975]: at listOnTimeout (internal/timers.js:554:17) Feb 14 19:58:45 tirion volumio[975]: at processTimers (internal/timers.js:497:7) Feb 14 19:58:45 tirion volumio[975]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 14 19:58:46 tirion kernel: hwmon hwmon1: Undervoltage detected! Feb 14 19:58:48 tirion sudo[13015]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-14 19:57 Feb 14 19:58:48 tirion sudo[13015]: 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"