Dec 17 13:22:00 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:00 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:00 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:00 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.0408647 s, 1.6 MB/s Dec 17 13:22:01 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:01 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:01 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:01 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.0179087 s, 3.7 MB/s Dec 17 13:22:01 volumio4 volumio[1155]: info: Setting Geolocation for MyVolumio to as1 Dec 17 13:22:01 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 13:22:01 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 13:22:01 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 13:22:02 volumio4 volumio[1155]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 17 13:22:02 volumio4 volumio[1155]: info: Updating MyVolumio device info Dec 17 13:22:02 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 13:22:02 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 13:22:02 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 17 13:22:03 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:03 volumio4 volumio[1155]: 1+1 records in Dec 17 13:22:03 volumio4 volumio[1155]: 1+1 records out Dec 17 13:22:03 volumio4 volumio[1155]: 61712 bytes (62 kB, 60 KiB) copied, 0.000661769 s, 93.3 MB/s Dec 17 13:22:03 volumio4 volumio[1155]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 17 13:22:04 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:04 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:04 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:04 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.000707445 s, 92.6 MB/s Dec 17 13:22:05 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:05 volumio4 volumio[1155]: 1+1 records in Dec 17 13:22:05 volumio4 volumio[1155]: 1+1 records out Dec 17 13:22:05 volumio4 volumio[1155]: 61712 bytes (62 kB, 60 KiB) copied, 0.038948 s, 1.6 MB/s Dec 17 13:22:07 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:07 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:07 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:07 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.0368351 s, 1.8 MB/s Dec 17 13:22:08 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:08 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:08 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:08 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.000657237 s, 99.7 MB/s Dec 17 13:22:09 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:09 volumio4 volumio[1155]: 1+1 records in Dec 17 13:22:09 volumio4 volumio[1155]: 1+1 records out Dec 17 13:22:09 volumio4 volumio[1155]: 61712 bytes (62 kB, 60 KiB) copied, 0.000638539 s, 96.6 MB/s Dec 17 13:22:10 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:10 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:10 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:10 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.000637029 s, 103 MB/s Dec 17 13:22:12 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:12 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:12 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:12 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.000653748 s, 100 MB/s Dec 17 13:22:13 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:13 volumio4 volumio[1155]: 1+1 records in Dec 17 13:22:13 volumio4 volumio[1155]: 1+1 records out Dec 17 13:22:13 volumio4 volumio[1155]: 61712 bytes (62 kB, 60 KiB) copied, 0.00945273 s, 6.5 MB/s Dec 17 13:22:14 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:14 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:14 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:14 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.0168281 s, 3.9 MB/s Dec 17 13:22:16 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:16 volumio4 volumio[1155]: 2+0 records in Dec 17 13:22:16 volumio4 volumio[1155]: 2+0 records out Dec 17 13:22:16 volumio4 volumio[1155]: 65536 bytes (66 kB, 64 KiB) copied, 0.0390162 s, 1.7 MB/s Dec 17 13:22:17 volumio4 volumio[1155]: /bin/dd: error reading '/tmp/fusiondspfifo': Resource temporarily unavailable Dec 17 13:22:17 volumio4 volumio[1155]: 8+1 records in Dec 17 13:22:17 volumio4 volumio[1155]: 8+1 records out Dec 17 13:22:17 volumio4 volumio[1155]: 276992 bytes (277 kB, 270 KiB) copied, 0.0188516 s, 14.7 MB/s Dec 17 13:22:18 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:18 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:18 volumio4 volumio[1155]: 0 bytes copied, 0.000295155 s, 0.0 kB/s Dec 17 13:22:20 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:20 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:20 volumio4 volumio[1155]: 0 bytes copied, 0.000267551 s, 0.0 kB/s Dec 17 13:22:21 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:21 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:21 volumio4 volumio[1155]: 0 bytes copied, 0.0384671 s, 0.0 kB/s Dec 17 13:22:22 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:22 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:22 volumio4 volumio[1155]: 0 bytes copied, 0.000266562 s, 0.0 kB/s Dec 17 13:22:23 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:23 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:23 volumio4 volumio[1155]: 0 bytes copied, 0.00029604 s, 0.0 kB/s Dec 17 13:22:25 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:25 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:25 volumio4 volumio[1155]: 0 bytes copied, 0.000300467 s, 0.0 kB/s Dec 17 13:22:26 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:26 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:26 volumio4 volumio[1155]: 0 bytes copied, 0.0384295 s, 0.0 kB/s Dec 17 13:22:27 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:27 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:27 volumio4 volumio[1155]: 0 bytes copied, 0.00679935 s, 0.0 kB/s Dec 17 13:22:29 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:29 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:29 volumio4 volumio[1155]: 0 bytes copied, 0.000283593 s, 0.0 kB/s Dec 17 13:22:29 volumio4 go-librespot[1531]: time="2025-12-17T13:22:29+07:00" level=trace msg="sent dealer ping" Dec 17 13:22:29 volumio4 go-librespot[1531]: time="2025-12-17T13:22:29+07:00" level=trace msg="received dealer pong" Dec 17 13:22:30 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:30 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:30 volumio4 volumio[1155]: 0 bytes copied, 0.000280155 s, 0.0 kB/s Dec 17 13:22:31 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:31 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:31 volumio4 volumio[1155]: 0 bytes copied, 0.000247551 s, 0.0 kB/s Dec 17 13:22:33 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:33 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:33 volumio4 volumio[1155]: 0 bytes copied, 0.00027927 s, 0.0 kB/s Dec 17 13:22:34 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:34 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:34 volumio4 volumio[1155]: 0 bytes copied, 0.0177803 s, 0.0 kB/s Dec 17 13:22:35 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:35 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:35 volumio4 volumio[1155]: 0 bytes copied, 0.000280156 s, 0.0 kB/s Dec 17 13:22:37 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:37 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:37 volumio4 volumio[1155]: 0 bytes copied, 0.000245833 s, 0.0 kB/s Dec 17 13:22:38 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:38 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:38 volumio4 volumio[1155]: 0 bytes copied, 0.000277238 s, 0.0 kB/s Dec 17 13:22:39 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:39 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:39 volumio4 volumio[1155]: 0 bytes copied, 0.000275988 s, 0.0 kB/s Dec 17 13:22:41 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:41 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:41 volumio4 volumio[1155]: 0 bytes copied, 0.000277603 s, 0.0 kB/s Dec 17 13:22:42 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:42 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:42 volumio4 volumio[1155]: 0 bytes copied, 0.000276405 s, 0.0 kB/s Dec 17 13:22:44 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:44 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:44 volumio4 volumio[1155]: 0 bytes copied, 0.000274791 s, 0.0 kB/s Dec 17 13:22:45 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:45 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:45 volumio4 volumio[1155]: 0 bytes copied, 0.0255594 s, 0.0 kB/s Dec 17 13:22:46 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:46 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:46 volumio4 volumio[1155]: 0 bytes copied, 0.00027776 s, 0.0 kB/s Dec 17 13:22:48 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:48 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:48 volumio4 volumio[1155]: 0 bytes copied, 0.000264009 s, 0.0 kB/s Dec 17 13:22:48 volumio4 volumio[1155]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 17 13:22:49 volumio4 go-librespot[1531]: time="2025-12-17T13:22:49+07:00" level=trace msg="received accesspoint ping" Dec 17 13:22:49 volumio4 go-librespot[1531]: time="2025-12-17T13:22:49+07:00" level=trace msg="received accesspoint pong ack" Dec 17 13:22:49 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:49 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:49 volumio4 volumio[1155]: 0 bytes copied, 0.000298124 s, 0.0 kB/s Dec 17 13:22:51 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:51 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:51 volumio4 volumio[1155]: 0 bytes copied, 0.000265311 s, 0.0 kB/s Dec 17 13:22:52 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:52 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:52 volumio4 volumio[1155]: 0 bytes copied, 0.000280208 s, 0.0 kB/s Dec 17 13:22:54 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:54 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:54 volumio4 volumio[1155]: 0 bytes copied, 0.0495947 s, 0.0 kB/s Dec 17 13:22:55 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:55 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:55 volumio4 volumio[1155]: 0 bytes copied, 0.000277811 s, 0.0 kB/s Dec 17 13:22:57 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:57 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:57 volumio4 volumio[1155]: 0 bytes copied, 0.000273488 s, 0.0 kB/s Dec 17 13:22:57 volumio4 volumio[1155]: info: CoreCommandRouter::volumioPlay Dec 17 13:22:57 volumio4 volumio[1155]: info: CoreStateMachine::play index undefined Dec 17 13:22:57 volumio4 volumio[1155]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 17 13:22:57 volumio4 volumio[1155]: info: CorePlayQueue::getTrack 0 Dec 17 13:22:57 volumio4 volumio[1155]: info: CoreStateMachine::startPlaybackTimer Dec 17 13:22:57 volumio4 volumio[1155]: info: CorePlayQueue::getTrack 0 Dec 17 13:22:57 volumio4 volumio[1155]: info: [1765952577614] ControllerSpotify::clearAddPlayTrack Dec 17 13:22:57 volumio4 volumio[1155]: info: Sending Spotify command with payload to local API: /player/play Dec 17 13:22:57 volumio4 go-librespot[1531]: time="2025-12-17T13:22:57+07:00" level=debug msg="resolved context of track" uri="spotify:track:12desdjBYDWjfEtJsR5aEq" Dec 17 13:22:57 volumio4 go-librespot[1531]: time="2025-12-17T13:22:57+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:12desdjBYDWjfEtJsR5aEq" Dec 17 13:22:57 volumio4 go-librespot[1531]: time="2025-12-17T13:22:57+07:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:12desdjBYDWjfEtJsR5aEq" Dec 17 13:22:57 volumio4 go-librespot[1531]: time="2025-12-17T13:22:57+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 17 13:22:57 volumio4 go-librespot[1531]: time="2025-12-17T13:22:57+07:00" level=trace msg="emitting websocket event: will_play" Dec 17 13:22:57 volumio4 volumio[1155]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:12desdjBYDWjfEtJsR5aEq","uri":"spotify:track:12desdjBYDWjfEtJsR5aEq","play_origin":"go-librespot"}} Dec 17 13:22:57 volumio4 go-librespot[1531]: time="2025-12-17T13:22:57+07:00" level=debug msg="selected format OGG_VORBIS_320 (f9094b04637b1871ed57e0f6640913e2914004c7)" uri="spotify:track:12desdjBYDWjfEtJsR5aEq" Dec 17 13:22:57 volumio4 go-librespot[1531]: time="2025-12-17T13:22:57+07:00" level=debug msg="requested aes key for file f9094b04637b1871ed57e0f6640913e2914004c7, gid: 12desdjBYDWjfEtJsR5aEq" Dec 17 13:22:58 volumio4 go-librespot[1531]: time="2025-12-17T13:22:58+07:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:12desdjBYDWjfEtJsR5aEq: failed retrieving audio key: failed retrieving aes key with code 1" Dec 17 13:22:58 volumio4 volumio[1155]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Dec 17 13:22:58 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:58 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:58 volumio4 volumio[1155]: 0 bytes copied, 0.000225625 s, 0.0 kB/s Dec 17 13:22:59 volumio4 volumio[1155]: 0+0 records in Dec 17 13:22:59 volumio4 volumio[1155]: 0+0 records out Dec 17 13:22:59 volumio4 volumio[1155]: 0 bytes copied, 0.000275624 s, 0.0 kB/s Dec 17 13:22:59 volumio4 go-librespot[1531]: time="2025-12-17T13:22:59+07:00" level=trace msg="sent dealer ping" Dec 17 13:22:59 volumio4 go-librespot[1531]: time="2025-12-17T13:22:59+07:00" level=trace msg="received dealer pong" Dec 17 13:23:01 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:01 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:01 volumio4 volumio[1155]: 0 bytes copied, 0.0198603 s, 0.0 kB/s Dec 17 13:23:02 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:02 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:02 volumio4 volumio[1155]: 0 bytes copied, 0.000260051 s, 0.0 kB/s Dec 17 13:23:03 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:03 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:03 volumio4 volumio[1155]: 0 bytes copied, 0.000277343 s, 0.0 kB/s Dec 17 13:23:05 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:05 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:05 volumio4 volumio[1155]: 0 bytes copied, 0.000270728 s, 0.0 kB/s Dec 17 13:23:06 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:06 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:06 volumio4 volumio[1155]: 0 bytes copied, 0.000296926 s, 0.0 kB/s Dec 17 13:23:08 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:08 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:08 volumio4 volumio[1155]: 0 bytes copied, 0.000277447 s, 0.0 kB/s Dec 17 13:23:09 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:09 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:09 volumio4 volumio[1155]: 0 bytes copied, 0.00030677 s, 0.0 kB/s Dec 17 13:23:10 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:10 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:10 volumio4 volumio[1155]: 0 bytes copied, 0.000276822 s, 0.0 kB/s Dec 17 13:23:12 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:12 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:12 volumio4 volumio[1155]: 0 bytes copied, 0.000238489 s, 0.0 kB/s Dec 17 13:23:13 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:13 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:13 volumio4 volumio[1155]: 0 bytes copied, 0.00027927 s, 0.0 kB/s Dec 17 13:23:14 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 17 13:23:14 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Dec 17 13:23:14 volumio4 volumio[1155]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 17 13:23:14 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:14 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:14 volumio4 volumio[1155]: 0 bytes copied, 0.000281353 s, 0.0 kB/s Dec 17 13:23:21 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:21 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:21 volumio4 volumio[1155]: 0 bytes copied, 0.000275155 s, 0.0 kB/s Dec 17 13:23:22 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:22 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:22 volumio4 volumio[1155]: 0 bytes copied, 0.000276301 s, 0.0 kB/s Dec 17 13:23:23 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:23 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:23 volumio4 volumio[1155]: 0 bytes copied, 0.000282083 s, 0.0 kB/s Dec 17 13:23:25 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:25 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:25 volumio4 volumio[1155]: 0 bytes copied, 0.000278072 s, 0.0 kB/s Dec 17 13:23:26 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:26 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:26 volumio4 volumio[1155]: 0 bytes copied, 0.00026302 s, 0.0 kB/s Dec 17 13:23:27 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:27 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:27 volumio4 volumio[1155]: 0 bytes copied, 0.000276353 s, 0.0 kB/s Dec 17 13:23:29 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:29 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:29 volumio4 volumio[1155]: 0 bytes copied, 0.000524685 s, 0.0 kB/s Dec 17 13:23:29 volumio4 go-librespot[1531]: time="2025-12-17T13:23:29+07:00" level=trace msg="sent dealer ping" Dec 17 13:23:29 volumio4 go-librespot[1531]: time="2025-12-17T13:23:29+07:00" level=trace msg="received dealer pong" Dec 17 13:23:30 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:30 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:30 volumio4 volumio[1155]: 0 bytes copied, 0.00052229 s, 0.0 kB/s Dec 17 13:23:31 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:31 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:31 volumio4 volumio[1155]: 0 bytes copied, 0.000286614 s, 0.0 kB/s Dec 17 13:23:32 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:32 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:32 volumio4 volumio[1155]: 0 bytes copied, 0.000528175 s, 0.0 kB/s Dec 17 13:23:32 volumio4 volumio[1155]: info: CoreCommandRouter::getUIConfigOnPlugin Dec 17 13:23:33 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:33 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:33 volumio4 volumio[1155]: 0 bytes copied, 0.000293644 s, 0.0 kB/s Dec 17 13:23:34 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:34 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:34 volumio4 volumio[1155]: 0 bytes copied, 0.000276718 s, 0.0 kB/s Dec 17 13:23:35 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:35 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:35 volumio4 volumio[1155]: 0 bytes copied, 0.00028328 s, 0.0 kB/s Dec 17 13:23:36 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:36 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:36 volumio4 volumio[1155]: 0 bytes copied, 0.000275208 s, 0.0 kB/s Dec 17 13:23:37 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:37 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:37 volumio4 volumio[1155]: 0 bytes copied, 0.000279113 s, 0.0 kB/s Dec 17 13:23:38 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:38 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:38 volumio4 volumio[1155]: 0 bytes copied, 0.000273333 s, 0.0 kB/s Dec 17 13:23:39 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:39 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:39 volumio4 volumio[1155]: 0 bytes copied, 0.000520258 s, 0.0 kB/s Dec 17 13:23:40 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:40 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:40 volumio4 volumio[1155]: 0 bytes copied, 0.000523852 s, 0.0 kB/s Dec 17 13:23:41 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:41 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:41 volumio4 volumio[1155]: 0 bytes copied, 0.000270572 s, 0.0 kB/s Dec 17 13:23:42 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:42 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:42 volumio4 volumio[1155]: 0 bytes copied, 0.000275051 s, 0.0 kB/s Dec 17 13:23:44 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:44 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:44 volumio4 volumio[1155]: 0 bytes copied, 0.000547446 s, 0.0 kB/s Dec 17 13:23:45 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:45 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:45 volumio4 volumio[1155]: 0 bytes copied, 0.000274791 s, 0.0 kB/s Dec 17 13:23:46 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:46 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:46 volumio4 volumio[1155]: 0 bytes copied, 0.000279166 s, 0.0 kB/s Dec 17 13:23:46 volumio4 volumio[1155]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 17 13:23:46 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 17 13:23:46 volumio4 volumio[1155]: info: Creating Spotify config file Dec 17 13:23:46 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 13:23:46 volumio4 volumio[1155]: info: Spotify config file written Dec 17 13:23:46 volumio4 sudo[2640]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 17 13:23:46 volumio4 sudo[2640]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 13:23:46 volumio4 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 17 13:23:46 volumio4 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 17 13:23:46 volumio4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 17 13:23:46 volumio4 systemd[1]: go-librespot-daemon.service: Consumed 1.267s CPU time. Dec 17 13:23:46 volumio4 volumio[1155]: info: Connection to go-librespot Websocket closed Dec 17 13:23:46 volumio4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 17 13:23:46 volumio4 sudo[2640]: pam_unix(sudo:session): session closed for user root Dec 17 13:23:46 volumio4 go-librespot[2642]: go-librespot daemon starting... Dec 17 13:23:46 volumio4 go-librespot[2643]: time="2025-12-17T13:23:46+07:00" level=info msg="running go-librespot 0.4.0" Dec 17 13:23:46 volumio4 go-librespot[2643]: time="2025-12-17T13:23:46+07:00" level=debug msg="app state loaded" Dec 17 13:23:46 volumio4 go-librespot[2643]: time="2025-12-17T13:23:46+07:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 17 13:23:47 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:47 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:47 volumio4 volumio[1155]: 0 bytes copied, 0.00053005 s, 0.0 kB/s Dec 17 13:23:48 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:48 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:48 volumio4 volumio[1155]: 0 bytes copied, 0.000273384 s, 0.0 kB/s Dec 17 13:23:49 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:49 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:49 volumio4 volumio[1155]: 0 bytes copied, 0.000273072 s, 0.0 kB/s Dec 17 13:23:49 volumio4 volumio[1155]: info: Initializing connection to go-librespot Websocket Dec 17 13:23:49 volumio4 go-librespot[2643]: time="2025-12-17T13:23:49+07:00" level=debug msg="new websocket client" Dec 17 13:23:49 volumio4 volumio[1155]: info: Connection to go-librespot Websocket established Dec 17 13:23:49 volumio4 volumio[1155]: info: go-librespot daemon successfully initialized Dec 17 13:23:50 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:50 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:50 volumio4 volumio[1155]: 0 bytes copied, 0.000509894 s, 0.0 kB/s Dec 17 13:23:51 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:51 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:51 volumio4 volumio[1155]: 0 bytes copied, 0.00028427 s, 0.0 kB/s Dec 17 13:23:52 volumio4 go-librespot[2643]: time="2025-12-17T13:23:52+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 17 13:23:52 volumio4 go-librespot[2643]: time="2025-12-17T13:23:52+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 17 13:23:52 volumio4 go-librespot[2643]: time="2025-12-17T13:23:52+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 17 13:23:52 volumio4 go-librespot[2643]: time="2025-12-17T13:23:52+07:00" level=info msg="zeroconf server listening on port 44391" Dec 17 13:23:52 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:52 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:52 volumio4 volumio[1155]: 0 bytes copied, 0.00028453 s, 0.0 kB/s Dec 17 13:23:52 volumio4 volumio[1155]: info: Getting Spotify volume Dec 17 13:23:52 volumio4 volumio[1155]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Dec 17 13:23:52 volumio4 volumio[1155]: info: Initializing connection to go-librespot Websocket Dec 17 13:23:52 volumio4 volumio[1155]: info: Connection to go-librespot Websocket established Dec 17 13:23:52 volumio4 go-librespot[2643]: time="2025-12-17T13:23:52+07:00" level=debug msg="new websocket client" Dec 17 13:23:52 volumio4 volumio[1155]: info: CoreCommandRouter::volumioGetState Dec 17 13:23:52 volumio4 volumio[1155]: info: CorePlayQueue::getTrack 0 Dec 17 13:23:52 volumio4 volumio[1155]: SPOTIFY: RECEIVED VOLUMIO VOLUME 70 Dec 17 13:23:53 volumio4 volumio[1155]: 0+0 records in Dec 17 13:23:53 volumio4 volumio[1155]: 0+0 records out Dec 17 13:23:53 volumio4 volumio[1155]: 0 bytes copied, 0.000418176 s, 0.0 kB/s Dec 17 13:23:54 volumio4 volumio[1155]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Dec 17 13:23:54 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Dec 17 13:23:54 volumio4 volumio[1155]: info: Creating Spotify config file Dec 17 13:23:54 volumio4 volumio[1155]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 17 13:23:54 volumio4 volumio[1155]: info: Spotify config file written Dec 17 13:23:54 volumio4 sudo[2711]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 17 13:23:54 volumio4 sudo[2711]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 17 13:23:54 volumio4 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 17 13:23:54 volumio4 systemd[1]: go-librespot-daemon.service: Killing process 2648 (go-librespot) with signal SIGKILL. Dec 17 13:23:54 volumio4 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 17 13:23:54 volumio4 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 17 13:23:54 volumio4 volumio[1155]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 17 13:23:54 volumio4 volumio[1155]: Error: socket hang up Dec 17 13:23:54 volumio4 volumio[1155]: at connResetException (node:internal/errors:720:14) Dec 17 13:23:54 volumio4 volumio[1155]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 17 13:23:54 volumio4 volumio[1155]: at Socket.emit (node:events:526:35) Dec 17 13:23:54 volumio4 volumio[1155]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 17 13:23:54 volumio4 volumio[1155]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 17 13:23:54 volumio4 volumio[1155]: code: 'ECONNRESET', Dec 17 13:23:54 volumio4 volumio[1155]: response: undefined Dec 17 13:23:54 volumio4 volumio[1155]: } Dec 17 13:23:54 volumio4 volumio[1155]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 17 13:23:54 volumio4 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 17 13:23:54 volumio4 go-librespot[2716]: go-librespot daemon starting... Dec 17 13:23:54 volumio4 sudo[2711]: pam_unix(sudo:session): session closed for user root Dec 17 13:23:54 volumio4 go-librespot[2720]: time="2025-12-17T13:23:54+07:00" level=info msg="running go-librespot 0.4.0" Dec 17 13:23:54 volumio4 go-librespot[2720]: time="2025-12-17T13:23:54+07:00" level=debug msg="app state loaded" Dec 17 13:23:54 volumio4 go-librespot[2720]: time="2025-12-17T13:23:54+07:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 17 13:23:55 volumio4 sudo[2738]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-17 13:22' Dec 17 13:23:55 volumio4 sudo[2738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"