-- Logs begin at Thu 2019-02-14 12:11:59 IST, end at Mon 2025-09-01 21:23:12 IDT. -- Sep 01 21:22:07 volumio volumio[817]: info: [ytcr] InnertubeLoader: obtaining po_token by visitorData... Sep 01 21:22:09 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Sep 01 21:22:09 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Sep 01 21:22:09 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Sep 01 21:22:09 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 Sep 01 21:22:09 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Sep 01 21:22:09 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Sep 01 21:22:09 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Sep 01 21:22:09 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Sep 01 21:22:11 volumio volumio-remote-updater[465]: [2025-09-01 21:22:11] [connect] Successful connection Sep 01 21:22:11 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Sep 01 21:22:11 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Sep 01 21:22:11 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Sep 01 21:22:11 volumio volumio[817]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Sep 01 21:22:11 volumio volumio-remote-updater[465]: [2025-09-01 21:22:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1756750931 101 Sep 01 21:22:11 volumio volumio[817]: 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: 13 Sep 01 21:22:11 volumio sudo[2771]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 21:22:11 volumio sudo[2771]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:22:11 volumio sudo[2769]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 21:22:11 volumio sudo[2769]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:22:11 volumio sudo[2771]: pam_unix(sudo:session): session closed for user root Sep 01 21:22:11 volumio sudo[2769]: pam_unix(sudo:session): session closed for user root Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:11 volumio volumio[817]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 14 Sep 01 21:22:11 volumio volumio[817]: info: [ytcr] InnertubeLoader: obtained po_token (expires in 43200 seconds) Sep 01 21:22:11 volumio volumio[817]: info: [ytcr] InnertubeLoader: re-create Innertube instance with po_token Sep 01 21:22:11 volumio volumio[817]: info: [ytcr] InnertubeLoader: creating Innertube instance with po_token... Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::volumioGetVisibleSources Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 01 21:22:11 volumio volumio[817]: info: Received Get System Info Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 21:22:11 volumio volumio[817]: info: Discovery: Getting this device information Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:11 volumio volumio[817]: info: Listing playlists Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 01 21:22:11 volumio volumio[817]: info: Received Get System Info Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 21:22:11 volumio volumio[817]: info: Discovery: Getting this device information Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:11 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 21:22:12 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 01 21:22:12 volumio volumio[817]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 21:22:12 volumio volumio[817]: info: FusionDsp - Sep 01 21:22:12 volumio volumio[817]: info: FusionDsp - undefined Sep 01 21:22:12 volumio volumio[817]: info: [yt-cast-receiver] Player.stop() Sep 01 21:22:12 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:12 volumio volumio[817]: info: CoreCommandRouter::servicePushState Sep 01 21:22:12 volumio volumio[817]: info: CoreStateMachine::pushState Sep 01 21:22:12 volumio volumio[817]: info: CoreCommandRouter::volumioPushState Sep 01 21:22:12 volumio volumio[817]: info: [yt-cast-receiver] Player.play(): vtnYuvcXpbk @ 66s Sep 01 21:22:12 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:12 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:12 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:13 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 01 21:22:13 volumio volumio[817]: info: Received Get System Info Sep 01 21:22:13 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 21:22:13 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 21:22:13 volumio volumio[817]: info: Discovery: Getting this device information Sep 01 21:22:13 volumio volumio[817]: info: CoreCommandRouter::volumioGetState Sep 01 21:22:13 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 21:22:13 volumio volumio[817]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Sep 01 21:22:13 volumio volumio[817]: [YOUTUBEJS][Player]: Failed to extract signature decipher algorithm. Sep 01 21:22:30 volumio go-librespot[1170]: time="2025-09-01T21:22:30+03:00" level=debug msg="obtained new client token: AAD0Lg0MrONeMBwc2UUGW+x8A3WEnkQVIflwV/B323f2Hn+C9xssampOiLyjYDhbyY8hnS+2WXMiqlsWCtUFS+eK57jMBAzHZOoaURC60tNQr69PlnGWwcHlYT4dRJmY/uyXEdPzaFUgqfgHxuGozQOnYEymNv/LYQtuSyOfeuqZ89Px0rWHua5kREqigU/qusuuQGmlP2Lhm6F4frQg7Y8g38xDMjI5B9i7ZcHYiGyuPwtWXrZ+tPEsIO4=" Sep 01 21:22:30 volumio go-librespot[1170]: time="2025-09-01T21:22:30+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 21:22:30 volumio go-librespot[1170]: time="2025-09-01T21:22:30+03:00" level=debug msg="completed keyexchange" Sep 01 21:22:30 volumio go-librespot[1170]: time="2025-09-01T21:22:30+03:00" level=debug msg="completed challenge" Sep 01 21:22:30 volumio go-librespot[1170]: time="2025-09-01T21:22:30+03:00" level=info msg="authenticated AP" username="a9*********************d3" Sep 01 21:22:30 volumio volumio[817]: <--- Last few GCs ---> Sep 01 21:22:30 volumio volumio[817]: [817:0x54c1788] 636502 ms: Mark-sweep 127.9 (131.8) -> 125.8 (129.9) MB, 560.1 / 0.2 ms (average mu = 0.339, current mu = 0.358) allocation failure scavenge might not succeed Sep 01 21:22:30 volumio volumio[817]: [817:0x54c1788] 637238 ms: Mark-sweep 125.8 (129.9) -> 125.8 (129.7) MB, 736.5 / 0.2 ms (average mu = 0.193, current mu = 0.000) allocation failure scavenge might not succeed Sep 01 21:22:30 volumio volumio[817]: <--- JS stacktrace ---> Sep 01 21:22:30 volumio volumio[817]: FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory Sep 01 21:22:31 volumio volumio-remote-updater[465]: [2025-09-01 21:22:31] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Sep 01 21:22:31 volumio volumio-remote-updater[465]: [2025-09-01 21:22:31] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=info msg="authenticated Login5" username="a9*********************d3" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=info msg="accepted zeroconf from ה-אברהם של S25 Ultra" username="a9*********************d3" Sep 01 21:22:31 volumio systemd[1]: volumio.service: Main process exited, code=killed, status=6/ABRT Sep 01 21:22:31 volumio systemd[1]: volumio.service: Failed with result 'signal'. Sep 01 21:22:31 volumio systemd[1]: Started dynamicswap service. Sep 01 21:22:31 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Sep 01 21:22:31 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Sep 01 21:22:31 volumio systemd[1]: Stopped Volumio Backend Module. Sep 01 21:22:31 volumio systemd[1]: Started Volumio Backend Module. Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="dealer connection opened" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=trace msg="starting accesspoint recv loop" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=trace msg="starting dealer recv loop" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=trace msg="received accesspoint ping" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="received connection id: Y2UxZjg2NDAtYjdk...QUREN0Y1NDlERA==" Sep 01 21:22:31 volumio systemd[1]: dynamicswap.service: Succeeded. Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=trace msg="received accesspoint pong ack" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="put connect state because NEW_DEVICE" Sep 01 21:22:31 volumio go-librespot[1170]: time="2025-09-01T21:22:31+03:00" level=debug msg="update volume requested to 65535/65535" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=trace msg="emitting websocket event: volume" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="handling transfer player command from 6e0b5ef165abb2750a1beeb6c82440ccdf5e737d" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="resolved context of track" uri="spotify:album:2rJ1Vr7wZKBQ3QvUSzNgXF" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:album:2rJ1Vr7wZKBQ3QvUSzNgXF" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="loading track (paused: false, position: 173670ms)" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=trace msg="emitting websocket event: will_play" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1124" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="selected format OGG_VORBIS_320 (40726344a036d09686737a94e9893f332eed62ac)" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=debug msg="requested aes key for file 40726344a036d09686737a94e9893f332eed62ac, gid: 2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:32 volumio go-librespot[1170]: time="2025-09-01T21:22:32+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:34 volumio go-librespot[1170]: time="2025-09-01T21:22:34+03:00" level=debug msg="fetched first chunk of 15, total size is 7495982 bytes" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:35 volumio volumio[2811]: info: ------------------------------------------- Sep 01 21:22:35 volumio volumio[2811]: info: ----- Volumio3 ---- Sep 01 21:22:35 volumio volumio[2811]: info: ------------------------------------------- Sep 01 21:22:35 volumio volumio[2811]: info: ----- System startup ---- Sep 01 21:22:35 volumio volumio[2811]: info: ------------------------------------------- Sep 01 21:22:35 volumio go-librespot[1170]: time="2025-09-01T21:22:35+03:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:35 volumio go-librespot[1170]: time="2025-09-01T21:22:35+03:00" level=debug msg="fetched chunk 14/14, size: 155950" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:35 volumio go-librespot[1170]: time="2025-09-01T21:22:35+03:00" level=trace msg="seek to 165000ms (diff: 280ms, samples: 7276500, bytes: 7482873)" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:35 volumio go-librespot[1170]: time="2025-09-01T21:22:35+03:00" level=debug msg="created new output device" Sep 01 21:22:36 volumio volumio-remote-updater[465]: [2025-09-01 21:22:36] [connect] Successful connection Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=info msg="loaded track \"הנה זה בא\" (paused: false, position: 173670ms, duration: 165000ms, prefetched: false)" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:2rOhIVZisqH7T87K6k6nT2" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="prefetching next track" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=trace msg="emitting websocket event: metadata" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=trace msg="emitting websocket event: active" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="sending successful reply for dealer request" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="selected format OGG_VORBIS_320 (8e561abb815cd33530c903d5c3605c2ac6505614)" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="requested aes key for file 8e561abb815cd33530c903d5c3605c2ac6505614, gid: 7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=trace msg="emitting websocket event: playing" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=info msg="playback was transferred to Home Assistant" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=trace msg="closed output device because of stop command" Sep 01 21:22:36 volumio volumio[2811]: info: MYVOLUMIO Environment detected Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=debug msg="put connect state inactive" Sep 01 21:22:36 volumio go-librespot[1170]: time="2025-09-01T21:22:36+03:00" level=trace msg="emitting websocket event: inactive" Sep 01 21:22:36 volumio go-librespot[1170]: panic: runtime error: invalid memory address or nil pointer dereference Sep 01 21:22:36 volumio go-librespot[1170]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x4 pc=0x62a854] Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 11 gp=0x30c5328 m=8 mp=0x30c0008 [running]: Sep 01 21:22:36 volumio go-librespot[1170]: panic({0x6c2b58, 0xc632b0}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/panic.go:779 +0x12c fp=0x2e277d8 sp=0x2e27784 pc=0x58b00 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.panicmem(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/panic.go:261 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.sigpanic() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/signal_unix.go:881 +0x39c fp=0x2e27808 sp=0x2e277d8 pc=0x74aec Sep 01 21:22:36 volumio go-librespot[1170]: main.(*AppPlayer).handlePlayerEvent(0x3030230, {0x852ad0, 0xcf1518}, 0x2e27a4c) Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/controls.go:148 +0x42c fp=0x2e278e4 sp=0x2e2780c pc=0x62a854 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*AppPlayer).Run(0x3030230, {0x852ad0, 0xcf1518}, 0x2c927c0) Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/player.go:607 +0x8e8 fp=0x2e27fd8 sp=0x2e278e4 pc=0x63a180 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*App).withAppPlayer.func3.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:358 +0x40 fp=0x2e27fec sp=0x2e27fd8 pc=0x632688 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2e27fec sp=0x2e27fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by main.(*App).withAppPlayer.func3 in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:358 +0x584 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 1 gp=0x2c02128 m=nil [select, 1 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c5ad30 sp=0x2c5ad1c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x2c5ae30, 0x2e25dfc, 0x0, 0x0, 0x2, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x2c5add0 sp=0x2c5ad30 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/zeroconf.(*Zeroconf).Serve(0x2caab40, 0x2c5aec0) Sep 01 21:22:36 volumio go-librespot[1170]: /src/zeroconf/zeroconf.go:283 +0x228 fp=0x2c5ae74 sp=0x2c5add0 pc=0x59c39c Sep 01 21:22:36 volumio go-librespot[1170]: main.(*App).withAppPlayer(0x2d34480, {0x852ad0, 0xcf1518}, 0x2c30200) Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:321 +0x554 fp=0x2c5af00 sp=0x2c5ae74 pc=0x631f44 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*App).Zeroconf(...) Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:170 Sep 01 21:22:36 volumio go-librespot[1170]: main.main() Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:548 +0x7f4 fp=0x2c5afa8 sp=0x2c5af00 pc=0x634510 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.main() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:271 +0x2fc fp=0x2c5afec sp=0x2c5afa8 pc=0x5ca38 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c5afec sp=0x2c5afec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 18 gp=0x2c84248 m=nil [force gc (idle), 3 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa5c, 0xcc5df0, 0x11, 0xa, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c407d4 sp=0x2c407c0 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goparkunlock(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:408 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.forcegchelper() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:326 +0xe4 fp=0x2c407ec sp=0x2c407d4 pc=0x5ce04 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c407ec sp=0x2c407ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by runtime.init.5 in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:314 +0x1c Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 19 gp=0x2c84368 m=nil [GC sweep wait]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa5c, 0xcc63f8, 0xc, 0x9, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c40fc4 sp=0x2c40fb0 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goparkunlock(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:408 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.bgsweep(0x2c92000) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgcsweep.go:318 +0x11c fp=0x2c40fe4 sp=0x2c40fc4 pc=0x45750 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gcenable.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:203 +0x28 fp=0x2c40fec sp=0x2c40fe4 pc=0x35870 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c40fec sp=0x2c40fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by runtime.gcenable in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:203 +0x74 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 20 gp=0x2c84488 m=nil [GC scavenge wait]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa5c, 0xcc6a20, 0xd, 0xa, 0x2) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c417b4 sp=0x2c417a0 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goparkunlock(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:408 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.(*scavengerState).park(0xcc6a20) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgcscavenge.go:425 +0x68 fp=0x2c417c8 sp=0x2c417b4 pc=0x42a70 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.bgscavenge(0x2c92000) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgcscavenge.go:658 +0x60 fp=0x2c417e4 sp=0x2c417c8 pc=0x431a8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gcenable.gowrap2() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:204 +0x28 fp=0x2c417ec sp=0x2c417e4 pc=0x3581c Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c417ec sp=0x2c417ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by runtime.gcenable in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:204 +0xbc Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 34 gp=0x2d14008 m=nil [finalizer wait]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7af908, 0xcf15b4, 0x10, 0xa, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2d1a78c sp=0x2d1a778 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.runfinq() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mfinal.go:194 +0x110 fp=0x2d1a7ec sp=0x2d1a78c pc=0x3465c Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2d1a7ec sp=0x2d1a7ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by runtime.createfing in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mfinal.go:164 +0x5c Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 2 gp=0x2d14fc8 m=nil [IO wait, 10 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605dec8, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c44d28 sp=0x2c44d14 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605deb8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x2c44d40 sp=0x2c44d28 pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605deb8, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x2c44d54 sp=0x2c44d40 pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2c281a8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x2c44d68 sp=0x2c44d54 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Accept(0x2c28190) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:611 +0x294 fp=0x2c44db0 sp=0x2c44d68 pc=0x10ea8c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).accept(0x2c28190) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_unix.go:172 +0x20 fp=0x2c44e18 sp=0x2c44db0 pc=0x17e3cc Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPListener).accept(0x2c26210) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/tcpsock_posix.go:159 +0x20 fp=0x2c44e30 sp=0x2c44e18 pc=0x196808 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPListener).Accept(0x2c26210) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/tcpsock.go:327 +0x30 fp=0x2c44e4c sp=0x2c44e30 pc=0x195874 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*onceCloseListener).Accept(0x2c96880) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x34 fp=0x2c44e64 sp=0x2c44e4c pc=0x362a5c Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Server).Serve(0x2ca4468, {0x852298, 0x2c26210}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/server.go:3255 +0x314 fp=0x2c44efc sp=0x2c44e64 pc=0x341118 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.Serve(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/server.go:2794 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*ConcreteApiServer).serve(0x2d48960) Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/api_server.go:611 +0x974 fp=0x2c44fe4 sp=0x2c44efc pc=0x627228 Sep 01 21:22:36 volumio go-librespot[1170]: main.NewApiServer.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/api_server.go:290 +0x28 fp=0x2c44fec sp=0x2c44fe4 pc=0x6260f8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c44fec sp=0x2c44fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by main.NewApiServer in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/api_server.go:290 +0x310 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 3 gp=0x2c846c8 m=nil [IO wait, 1 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605dce8, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c56e84 sp=0x2c56e70 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605dcd8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x2c56e9c sp=0x2c56e84 pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605dcd8, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x2c56eb0 sp=0x2c56e9c pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2fe98c8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x2c56ec4 sp=0x2c56eb0 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).RawRead(0x2fe98b0, 0x30f3950) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:708 +0x164 fp=0x2c56ef0 sp=0x2c56ec4 pc=0x10f690 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*rawConn).Read(0x2ef74c8, 0x30f3950) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/rawconn.go:44 +0x38 fp=0x2c56f10 sp=0x2c56ef0 pc=0x190c30 Sep 01 21:22:36 volumio go-librespot[1170]: golang.org/x/net/internal/socket.(*Conn).recvMsg(0x2fd7980, 0x30f3920, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/golang.org/x/net@v0.26.0/internal/socket/rawconn_msg.go:27 +0x154 fp=0x2c56f40 sp=0x2c56f10 pc=0x53cb38 Sep 01 21:22:36 volumio go-librespot[1170]: golang.org/x/net/internal/socket.(*Conn).RecvMsg(...) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/golang.org/x/net@v0.26.0/internal/socket/socket.go:247 Sep 01 21:22:36 volumio go-librespot[1170]: golang.org/x/net/ipv4.(*payloadHandler).ReadFrom(0x30f2308, {0x3050000, 0x10000, 0x10000}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/golang.org/x/net@v0.26.0/ipv4/payload_cmsg.go:31 +0x44c fp=0x2c56f9c sp=0x2c56f40 pc=0x540b20 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/grandcat/zeroconf.(*Server).recv4(0x2fbb840, 0x30f2300) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:254 +0xec fp=0x2c56fe0 sp=0x2c56f9c pc=0x5973b0 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/grandcat/zeroconf.(*Server).mainloop.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:188 +0x30 fp=0x2c56fec sp=0x2c56fe0 pc=0x597068 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c56fec sp=0x2c56fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by github.com/grandcat/zeroconf.(*Server).mainloop in goroutine 53 Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:188 +0x7c Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 10 gp=0x2d15448 m=nil [runnable]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x301ce74 sp=0x301ce60 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x301cf74, 0x301cf3c, 0x0, 0x0, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x301cf14 sp=0x301ce74 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/player.(*Player).manageLoop(0x2f1f220) Sep 01 21:22:36 volumio go-librespot[1170]: /src/player/player.go:190 +0x1fc fp=0x301cfe4 sp=0x301cf14 pc=0x508558 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/player.NewPlayer.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/player/player.go:172 +0x28 fp=0x301cfec sp=0x301cfe4 pc=0x508138 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x301cfec sp=0x301cfec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by github.com/devgianlu/go-librespot/player.NewPlayer in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /src/player/player.go:172 +0x1f8 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 24 gp=0x2c84908 m=nil [GC worker (idle)]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7af918, 0x2e8d170, 0x1a, 0xa, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c42790 sp=0x2c4277c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gcBgMarkWorker() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:1310 +0xec fp=0x2c427ec sp=0x2c42790 pc=0x38498 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c427ec sp=0x2c427ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by runtime.gcBgMarkStartWorkers in goroutine 22 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:1234 +0x20 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 25 gp=0x2c84a28 m=nil [GC worker (idle)]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7af918, 0x2e8d188, 0x1a, 0xa, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c42f90 sp=0x2c42f7c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gcBgMarkWorker() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:1310 +0xec fp=0x2c42fec sp=0x2c42f90 pc=0x38498 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c42fec sp=0x2c42fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by runtime.gcBgMarkStartWorkers in goroutine 22 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:1234 +0x20 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 26 gp=0x2c84b48 m=nil [GC worker (idle)]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7af918, 0x2e8d1a0, 0x1a, 0xa, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c43790 sp=0x2c4377c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gcBgMarkWorker() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:1310 +0xec fp=0x2c437ec sp=0x2c43790 pc=0x38498 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c437ec sp=0x2c437ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by runtime.gcBgMarkStartWorkers in goroutine 22 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:1234 +0x20 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 27 gp=0x2c84c68 m=nil [GC worker (idle)]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7af918, 0x2e8d1b8, 0x1a, 0xa, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c43f90 sp=0x2c43f7c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gcBgMarkWorker() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:1310 +0xec fp=0x2c43fec sp=0x2c43f90 pc=0x38498 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c43fec sp=0x2c43fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by runtime.gcBgMarkStartWorkers in goroutine 22 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:1234 +0x20 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 55 gp=0x30c47e8 m=nil [chan receive, 10 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7af8ec, 0x2d101b0, 0xe, 0x7, 0x2) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c45748 sp=0x2c45734 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.chanrecv(0x2d10180, 0x2c457d0, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/chan.go:583 +0x4b0 fp=0x2c45784 sp=0x2c45748 pc=0x1ff80 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.chanrecv2(0x2d10180, 0x2c457d0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/chan.go:447 +0x20 fp=0x2c45798 sp=0x2c45784 pc=0x1fac4 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*App).withAppPlayer.func1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:268 +0x68 fp=0x2c457ec sp=0x2c45798 pc=0x632b84 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c457ec sp=0x2c457ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by main.(*App).withAppPlayer in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:265 +0x464 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 56 gp=0x30c4908 m=nil [runnable]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gcTrigger.test({0x0, 0x0, 0x0}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/mgc.go:568 +0x1e0 fp=0x2c45d00 sp=0x2c45d00 pc=0x35e6c Sep 01 21:22:36 volumio go-librespot[1170]: runtime.mallocgc(0x44, 0x6dea38, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/malloc.go:1307 +0xa64 fp=0x2c45d48 sp=0x2c45d00 pc=0x27354 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.newobject(0x6dea38) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/malloc.go:1390 +0x2c fp=0x2c45d5c sp=0x2c45d48 pc=0x275e4 Sep 01 21:22:36 volumio go-librespot[1170]: context.WithDeadlineCause({0x852ab0, 0xcf1518}, {0xc22596fc6f190f5b, 0x8decf4e714, 0xcc6880}, {0x0, 0x0}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/context/context.go:626 +0xb4 fp=0x2c45dc4 sp=0x2c45d5c pc=0xc37f4 Sep 01 21:22:36 volumio go-librespot[1170]: context.WithDeadline(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/context/context.go:612 Sep 01 21:22:36 volumio go-librespot[1170]: context.WithTimeout({0x852ab0, 0xcf1518}, 0x12a05f200) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/context/context.go:690 +0x88 fp=0x2c45e34 sp=0x2c45dc4 pc=0xc4094 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).writeControl(0x2e0c648, {0x852ab0, 0xcf1518}, 0x8, {0x301a01a, 0x2, 0x2}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/write.go:233 +0x54 fp=0x2c45e84 sp=0x2c45e34 pc=0x47be04 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).writeClose(0x2e0c648, 0x3e9, {0x0, 0x0}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:76 +0x1a0 fp=0x2c45f08 sp=0x2c45e84 pc=0x4706b0 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).closeHandshake(0x2e0c648, 0x3e9, {0x0, 0x0}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:37 +0x80 fp=0x2c45f48 sp=0x2c45f08 pc=0x470254 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).Close(...) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:31 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/dealer.(*Dealer).Close(0x2d74168) Sep 01 21:22:36 volumio go-librespot[1170]: /src/dealer/dealer.go:119 +0xd4 fp=0x2c45f78 sp=0x2c45f48 pc=0x52603c Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/session.(*Session).Close(0x2d12540) Sep 01 21:22:36 volumio go-librespot[1170]: /src/session/session.go:218 +0xa8 fp=0x2c45f90 sp=0x2c45f78 pc=0x53c080 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*AppPlayer).Close(...) Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/player.go:564 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*App).withAppPlayer.func2() Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:290 +0xf0 fp=0x2c45fec sp=0x2c45f90 pc=0x6327a4 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c45fec sp=0x2c45fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by main.(*App).withAppPlayer in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/main.go:281 +0x504 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 4 gp=0x2c02ea8 m=nil [IO wait, 10 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605dc48, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c4465c sp=0x2c44648 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605dc38, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x2c44674 sp=0x2c4465c pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605dc38, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x2c44688 sp=0x2c44674 pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2fe9918, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x2c4469c sp=0x2c44688 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).RawRead(0x2fe9900, 0x2ee00f0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:708 +0x164 fp=0x2c446c8 sp=0x2c4469c pc=0x10f690 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*rawConn).Read(0x2ef74e8, 0x2ee00f0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/rawconn.go:44 +0x38 fp=0x2c446e8 sp=0x2c446c8 pc=0x190c30 Sep 01 21:22:36 volumio go-librespot[1170]: golang.org/x/net/internal/socket.(*Conn).recvMsg(0x2fd7990, 0x2ee00c0, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/golang.org/x/net@v0.26.0/internal/socket/rawconn_msg.go:27 +0x154 fp=0x2c44718 sp=0x2c446e8 pc=0x53cb38 Sep 01 21:22:36 volumio go-librespot[1170]: golang.org/x/net/internal/socket.(*Conn).RecvMsg(...) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/golang.org/x/net@v0.26.0/internal/socket/socket.go:247 Sep 01 21:22:36 volumio go-librespot[1170]: golang.org/x/net/ipv6.(*payloadHandler).ReadFrom(0x30f2338, {0x3040000, 0x10000, 0x10000}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/golang.org/x/net@v0.26.0/ipv6/payload_cmsg.go:31 +0x2ec fp=0x2c4479c sp=0x2c44718 pc=0x5444a8 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/grandcat/zeroconf.(*Server).recv6(0x2fbb840, 0x30f2330) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:282 +0xec fp=0x2c447e0 sp=0x2c4479c pc=0x5975a4 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/grandcat/zeroconf.(*Server).mainloop.gowrap2() Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:191 +0x30 fp=0x2c447ec sp=0x2c447e0 pc=0x59700c Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c447ec sp=0x2c447ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by github.com/grandcat/zeroconf.(*Server).mainloop in goroutine 53 Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/grandcat/zeroconf@v1.0.0/server.go:191 +0xe8 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 57 gp=0x30c4a28 m=nil [IO wait, 1 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605dd88, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c465e8 sp=0x2c465d4 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605dd78, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x2c46600 sp=0x2c465e8 pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605dd78, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x2c46614 sp=0x2c46600 pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2fe9878, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x2c46628 sp=0x2c46614 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Accept(0x2fe9860) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:611 +0x294 fp=0x2c46670 sp=0x2c46628 pc=0x10ea8c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).accept(0x2fe9860) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_unix.go:172 +0x20 fp=0x2c466d8 sp=0x2c46670 pc=0x17e3cc Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPListener).accept(0x30e1098) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/tcpsock_posix.go:159 +0x20 fp=0x2c466f0 sp=0x2c466d8 pc=0x196808 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPListener).Accept(0x30e1098) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/tcpsock.go:327 +0x30 fp=0x2c4670c sp=0x2c466f0 pc=0x195874 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*onceCloseListener).Accept(0x2fb91a0) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x34 fp=0x2c46724 sp=0x2c4670c pc=0x362a5c Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Server).Serve(0x2fcc008, {0x852298, 0x30e1098}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/server.go:3255 +0x314 fp=0x2c467bc sp=0x2c46724 pc=0x341118 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.Serve(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/server.go:2794 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/zeroconf.(*Zeroconf).Serve.func2() Sep 01 21:22:36 volumio go-librespot[1170]: /src/zeroconf/zeroconf.go:280 +0x8c fp=0x2c467ec sp=0x2c467bc pc=0x59c498 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c467ec sp=0x2c467ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by github.com/devgianlu/go-librespot/zeroconf.(*Zeroconf).Serve in goroutine 1 Sep 01 21:22:36 volumio go-librespot[1170]: /src/zeroconf/zeroconf.go:280 +0x160 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 119 gp=0x30c50e8 m=nil [select]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x3022eb0 sp=0x3022e9c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x3022fac, 0x3022f78, 0x0, 0x0, 0x2, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x3022f50 sp=0x3022eb0 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*persistConn).writeLoop(0x2ceac68) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:2444 +0xd0 fp=0x3022fe4 sp=0x3022f50 pc=0x357b24 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Transport).dialConn.gowrap3() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1800 +0x28 fp=0x3022fec sp=0x3022fe4 pc=0x354930 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x3022fec sp=0x3022fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*Transport).dialConn in goroutine 136 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1800 +0x1444 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 100 gp=0x2c84fc8 m=nil [select, 1 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2d1d6b8 sp=0x2d1d6a4 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x2d1d7d4, 0x2d1d77c, 0x0, 0x0, 0x2, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x2d1d758 sp=0x2d1d6b8 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/ap.(*Accesspoint).pongAckTicker(0x2d8a588) Sep 01 21:22:36 volumio go-librespot[1170]: /src/ap/ap.go:355 +0x8c fp=0x2d1d7e4 sp=0x2d1d758 pc=0x48abe4 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/ap.(*Accesspoint).Receive.(*Accesspoint).startReceiving.func1.gowrap2() Sep 01 21:22:36 volumio go-librespot[1170]: /src/ap/ap.go:264 +0x28 fp=0x2d1d7ec sp=0x2d1d7e4 pc=0x48a2dc Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2d1d7ec sp=0x2d1d7ec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by github.com/devgianlu/go-librespot/ap.(*Accesspoint).Receive.(*Accesspoint).startReceiving.func1 in goroutine 11 Sep 01 21:22:36 volumio go-librespot[1170]: /src/ap/ap.go:264 +0x15c Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 118 gp=0x2d14368 m=nil [IO wait]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605d888, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x303dafc sp=0x303dae8 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605d878, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x303db14 sp=0x303dafc pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605d878, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x303db28 sp=0x303db14 pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2f1f288, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x303db3c sp=0x303db28 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Read(0x2f1f270, {0x314e000, 0xa000, 0xa000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:164 +0x238 fp=0x303db84 sp=0x303db3c pc=0x10b40c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).Read(0x2f1f270, {0x314e000, 0xa000, 0xa000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_posix.go:55 +0x38 fp=0x303dbb0 sp=0x303db84 pc=0x17c4d8 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*conn).Read(0x2c30008, {0x314e000, 0xa000, 0xa000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/net.go:179 +0x48 fp=0x303dbdc sp=0x303dbb0 pc=0x18c9f4 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPConn).Read(0x2c30008, {0x314e000, 0xa000, 0xa000}) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x44 fp=0x303dbfc sp=0x303dbdc pc=0x19fc48 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*atLeastReader).Read(0x3012100, {0x314e000, 0xa000, 0xa000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:806 +0x78 fp=0x303dc28 sp=0x303dbfc pc=0x27c588 Sep 01 21:22:36 volumio go-librespot[1170]: bytes.(*Buffer).ReadFrom(0x2ee3c8c, {0x84ed44, 0x3012100}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bytes/buffer.go:211 +0xa4 fp=0x303dc64 sp=0x303dc28 pc=0x139ad8 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readFromUntil(0x2ee3b08, {0x84df04, 0x2c30008}, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:828 +0xd4 fp=0x303dc8c sp=0x303dc64 pc=0x27c7e4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecordOrCCS(0x2ee3b08, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:626 +0x134 fp=0x303ddf0 sp=0x303dc8c pc=0x279ee4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecord(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:588 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).Read(0x2ee3b08, {0x30b3000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:1370 +0x15c fp=0x303de20 sp=0x303ddf0 pc=0x27fd54 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*persistConn).Read(0x2ceac68, {0x30b3000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1977 +0x16c fp=0x303de54 sp=0x303de20 pc=0x3554d4 Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).fill(0x30f2660) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:110 +0x10c fp=0x303de78 sp=0x303de54 pc=0x2bdcbc Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).Peek(0x30f2660, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:148 +0x68 fp=0x303de84 sp=0x303de78 pc=0x2bde40 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*persistConn).readLoop(0x2ceac68) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:2141 +0x194 fp=0x303dfe4 sp=0x303de84 pc=0x356064 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Transport).dialConn.gowrap2() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1799 +0x28 fp=0x303dfec sp=0x303dfe4 pc=0x354984 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x303dfec sp=0x303dfec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*Transport).dialConn in goroutine 136 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1799 +0x13f4 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 70 gp=0x2d14488 m=nil [IO wait, 1 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605db08, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x3036ad4 sp=0x3036ac0 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605daf8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x3036aec sp=0x3036ad4 pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605daf8, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x3036b00 sp=0x3036aec pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2ca2748, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x3036b14 sp=0x3036b00 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Read(0x2ca2730, {0x2e2c000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:164 +0x238 fp=0x3036b5c sp=0x3036b14 pc=0x10b40c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).Read(0x2ca2730, {0x2e2c000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_posix.go:55 +0x38 fp=0x3036b88 sp=0x3036b5c pc=0x17c4d8 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*conn).Read(0x3018c00, {0x2e2c000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/net.go:179 +0x48 fp=0x3036bb4 sp=0x3036b88 pc=0x18c9f4 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPConn).Read(0x3018c00, {0x2e2c000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x44 fp=0x3036bd4 sp=0x3036bb4 pc=0x19fc48 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*atLeastReader).Read(0x2d0a400, {0x2e2c000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:806 +0x78 fp=0x3036c00 sp=0x3036bd4 pc=0x27c588 Sep 01 21:22:36 volumio go-librespot[1170]: bytes.(*Buffer).ReadFrom(0x2c13c8c, {0x84ed44, 0x2d0a400}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bytes/buffer.go:211 +0xa4 fp=0x3036c3c sp=0x3036c00 pc=0x139ad8 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readFromUntil(0x2c13b08, {0x84df04, 0x3018c00}, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:828 +0xd4 fp=0x3036c64 sp=0x3036c3c pc=0x27c7e4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecordOrCCS(0x2c13b08, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:626 +0x134 fp=0x3036dc8 sp=0x3036c64 pc=0x279ee4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecord(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:588 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).Read(0x2c13b08, {0x2e3c000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:1370 +0x15c fp=0x3036df8 sp=0x3036dc8 pc=0x27fd54 Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).Read(0x30f33e0, {0x2d34324, 0x9, 0x9}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:241 +0x214 fp=0x3036e1c sp=0x3036df8 pc=0x2be348 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadAtLeast({0x84e0f8, 0x30f33e0}, {0x2d34324, 0x9, 0x9}, 0x9) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:335 +0x90 fp=0x3036e48 sp=0x3036e1c pc=0x1041c8 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadFull(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:354 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.http2readFrameHeader({0x2d34324, 0x9, 0x9}, {0x84e0f8, 0x30f33e0}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:1638 +0x54 fp=0x3036e70 sp=0x3036e48 pc=0x2f7244 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Framer).ReadFrame(0x2d34300) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:1902 +0x88 fp=0x3036eec sp=0x3036e70 pc=0x2f79dc Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2clientConnReadLoop).run(0x3036fdc) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:9334 +0x150 fp=0x3036fa4 sp=0x3036eec pc=0x31c1f8 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2ClientConn).readLoop(0x2da7308) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:9229 +0x68 fp=0x3036fe4 sp=0x3036fa4 pc=0x31b6ec Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Transport).newClientConn.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7879 +0x28 fp=0x3036fec sp=0x3036fe4 pc=0x314738 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x3036fec sp=0x3036fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*http2Transport).newClientConn in goroutine 69 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7879 +0xcb0 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 99 gp=0x2d146c8 m=nil [IO wait]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605da68, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c59d14 sp=0x2c59d00 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605da58, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x2c59d2c sp=0x2c59d14 pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605da58, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x2c59d40 sp=0x2c59d2c pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2d06658, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x2c59d54 sp=0x2c59d40 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Read(0x2d06640, {0x2ca6dcc, 0x3, 0x3}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:164 +0x238 fp=0x2c59d9c sp=0x2c59d54 pc=0x10b40c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).Read(0x2d06640, {0x2ca6dcc, 0x3, 0x3}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_posix.go:55 +0x38 fp=0x2c59dc8 sp=0x2c59d9c pc=0x17c4d8 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*conn).Read(0x2c942a0, {0x2ca6dcc, 0x3, 0x3}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/net.go:179 +0x48 fp=0x2c59df4 sp=0x2c59dc8 pc=0x18c9f4 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPConn).Read(0x2c942a0, {0x2ca6dcc, 0x3, 0x3}) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x44 fp=0x2c59e14 sp=0x2c59df4 pc=0x19fc48 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadAtLeast({0x84df04, 0x2c942a0}, {0x2ca6dcc, 0x3, 0x3}, 0x3) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:335 +0x90 fp=0x2c59e40 sp=0x2c59e14 pc=0x1041c8 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadFull(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:354 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/ap.(*shannonConn).receivePacket(0x2c7f7c0, {0x852ad0, 0xcf1518}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/ap/shannon.go:124 +0x3a0 fp=0x2c59f04 sp=0x2c59e40 pc=0x48db88 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/ap.(*Accesspoint).recvLoop(0x2d8a588) Sep 01 21:22:36 volumio go-librespot[1170]: /src/ap/ap.go:276 +0x68 fp=0x2c59fe4 sp=0x2c59f04 pc=0x48a3c4 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/ap.(*Accesspoint).Receive.(*Accesspoint).startReceiving.func1.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/ap/ap.go:260 +0x28 fp=0x2c59fec sp=0x2c59fe4 pc=0x48a330 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c59fec sp=0x2c59fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by github.com/devgianlu/go-librespot/ap.(*Accesspoint).Receive.(*Accesspoint).startReceiving.func1 in goroutine 11 Sep 01 21:22:36 volumio go-librespot[1170]: /src/ap/ap.go:260 +0x98 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 87 gp=0x30c5208 m=nil [IO wait, 1 minutes]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605d9c8, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x303cad4 sp=0x303cac0 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605d9b8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x303caec sp=0x303cad4 pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605d9b8, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x303cb00 sp=0x303caec pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2d066f8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x303cb14 sp=0x303cb00 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Read(0x2d066e0, {0x2e83000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:164 +0x238 fp=0x303cb5c sp=0x303cb14 pc=0x10b40c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).Read(0x2d066e0, {0x2e83000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_posix.go:55 +0x38 fp=0x303cb88 sp=0x303cb5c pc=0x17c4d8 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*conn).Read(0x2d00230, {0x2e83000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/net.go:179 +0x48 fp=0x303cbb4 sp=0x303cb88 pc=0x18c9f4 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPConn).Read(0x2d00230, {0x2e83000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x44 fp=0x303cbd4 sp=0x303cbb4 pc=0x19fc48 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*atLeastReader).Read(0x2d0a610, {0x2e83000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:806 +0x78 fp=0x303cc00 sp=0x303cbd4 pc=0x27c588 Sep 01 21:22:36 volumio go-librespot[1170]: bytes.(*Buffer).ReadFrom(0x2d7af0c, {0x84ed44, 0x2d0a610}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bytes/buffer.go:211 +0xa4 fp=0x303cc3c sp=0x303cc00 pc=0x139ad8 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readFromUntil(0x2d7ad88, {0x84df04, 0x2d00230}, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:828 +0xd4 fp=0x303cc64 sp=0x303cc3c pc=0x27c7e4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecordOrCCS(0x2d7ad88, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:626 +0x134 fp=0x303cdc8 sp=0x303cc64 pc=0x279ee4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecord(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:588 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).Read(0x2d7ad88, {0x2ea3000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:1370 +0x15c fp=0x303cdf8 sp=0x303cdc8 pc=0x27fd54 Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).Read(0x2ee1470, {0x2cbe324, 0x9, 0x9}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:241 +0x214 fp=0x303ce1c sp=0x303cdf8 pc=0x2be348 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadAtLeast({0x84e0f8, 0x2ee1470}, {0x2cbe324, 0x9, 0x9}, 0x9) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:335 +0x90 fp=0x303ce48 sp=0x303ce1c pc=0x1041c8 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadFull(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:354 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.http2readFrameHeader({0x2cbe324, 0x9, 0x9}, {0x84e0f8, 0x2ee1470}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:1638 +0x54 fp=0x303ce70 sp=0x303ce48 pc=0x2f7244 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Framer).ReadFrame(0x2cbe300) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:1902 +0x88 fp=0x303ceec sp=0x303ce70 pc=0x2f79dc Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2clientConnReadLoop).run(0x303cfdc) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:9334 +0x150 fp=0x303cfa4 sp=0x303ceec pc=0x31c1f8 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2ClientConn).readLoop(0x2cb2508) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:9229 +0x68 fp=0x303cfe4 sp=0x303cfa4 pc=0x31b6ec Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Transport).newClientConn.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7879 +0x28 fp=0x303cfec sp=0x303cfe4 pc=0x314738 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x303cfec sp=0x303cfec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*http2Transport).newClientConn in goroutine 86 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7879 +0xcb0 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 98 gp=0x2d147e8 m=nil [select]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2d16ea8 sp=0x2d16e94 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x2d16fa4, 0x2d16f6c, 0x0, 0x0, 0x5, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x2d16f48 sp=0x2d16ea8 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).timeoutLoop(0x2e0c648) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:153 +0x10c fp=0x2d16fe4 sp=0x2d16f48 pc=0x4727cc Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.newConn.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x28 fp=0x2d16fec sp=0x2d16fe4 pc=0x4723c0 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2d16fec sp=0x2d16fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by nhooyr.io/websocket.newConn in goroutine 11 Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/conn_notjs.go:114 +0x544 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 101 gp=0x2d14908 m=nil [IO wait]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605de28, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2f2f940 sp=0x2f2f92c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605de18, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x2f2f958 sp=0x2f2f940 pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605de18, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x2f2f96c sp=0x2f2f958 pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2d06888, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x2f2f980 sp=0x2f2f96c pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Read(0x2d06870, {0x2f42000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:164 +0x238 fp=0x2f2f9c8 sp=0x2f2f980 pc=0x10b40c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).Read(0x2d06870, {0x2f42000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_posix.go:55 +0x38 fp=0x2f2f9f4 sp=0x2f2f9c8 pc=0x17c4d8 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*conn).Read(0x2c95d08, {0x2f42000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/net.go:179 +0x48 fp=0x2f2fa20 sp=0x2f2f9f4 pc=0x18c9f4 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPConn).Read(0x2c95d08, {0x2f42000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x44 fp=0x2f2fa40 sp=0x2f2fa20 pc=0x19fc48 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*atLeastReader).Read(0x2ed80f0, {0x2f42000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:806 +0x78 fp=0x2f2fa6c sp=0x2f2fa40 pc=0x27c588 Sep 01 21:22:36 volumio go-librespot[1170]: bytes.(*Buffer).ReadFrom(0x2ee380c, {0x84ed44, 0x2ed80f0}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bytes/buffer.go:211 +0xa4 fp=0x2f2faa8 sp=0x2f2fa6c pc=0x139ad8 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readFromUntil(0x2ee3688, {0x84df04, 0x2c95d08}, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:828 +0xd4 fp=0x2f2fad0 sp=0x2f2faa8 pc=0x27c7e4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecordOrCCS(0x2ee3688, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:626 +0x134 fp=0x2f2fc34 sp=0x2f2fad0 pc=0x279ee4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecord(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:588 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).Read(0x2ee3688, {0x2e3d000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:1370 +0x15c fp=0x2f2fc64 sp=0x2f2fc34 pc=0x27fd54 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*readWriteCloserBody).Read(0x2f764e0, {0x2e3d000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:2429 +0xec fp=0x2f2fc84 sp=0x2f2fc64 pc=0x357a08 Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).fill(0x30f3a10) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:110 +0x10c fp=0x2f2fca8 sp=0x2f2fc84 pc=0x2bdcbc Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).ReadByte(0x30f3a10) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:269 +0x28 fp=0x2f2fcb4 sp=0x2f2fca8 pc=0x2be540 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.readFrameHeader(0x30f3a10, {0x2e0c678, 0x8, 0x8}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/frame.go:54 +0x74 fp=0x2f2fcf4 sp=0x2f2fcb4 pc=0x475920 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).readFrameHeader(0x2e0c648, {0x852ab0, 0xcf1518}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/read.go:188 +0xb4 fp=0x2f2fdb4 sp=0x2f2fcf4 pc=0x478584 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).readLoop(0x2e0c648, {0x852ab0, 0xcf1518}) Sep 01 21:22:36 volumio volumio[2811]: info: Plugin folders cleanup Sep 01 21:22:36 volumio volumio[2811]: info: Scanning into folder /volumio/app/plugins/ Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category audio_interface Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category miscellanea Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category music_service Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category plugins.json Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category system_controller Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/read.go:146 +0x3c fp=0x2f2fe78 sp=0x2f2fdb4 pc=0x47806c Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).reader(0x2e0c648, {0x852ab0, 0xcf1518}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/read.go:315 +0x108 fp=0x2f2ff04 sp=0x2f2fe78 pc=0x479280 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).Reader(...) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/read.go:30 Sep 01 21:22:36 volumio go-librespot[1170]: nhooyr.io/websocket.(*Conn).Read(0x2e0c648, {0x852ab0, 0xcf1518}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/nhooyr.io/websocket@v1.8.7/read.go:36 +0x30 fp=0x2f2ff2c sp=0x2f2ff04 pc=0x477950 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/dealer.(*Dealer).recvLoop(0x2d74168) Sep 01 21:22:36 volumio go-librespot[1170]: /src/dealer/dealer.go:188 +0x58 fp=0x2f2ffe4 sp=0x2f2ff2c pc=0x5265f4 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/dealer.(*Dealer).ReceiveMessage.(*Dealer).startReceiving.func1.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/dealer/dealer.go:125 +0x28 fp=0x2f2ffec sp=0x2f2ffe4 pc=0x5280cc Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2f2ffec sp=0x2f2ffec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by github.com/devgianlu/go-librespot/dealer.(*Dealer).ReceiveMessage.(*Dealer).startReceiving.func1 in goroutine 11 Sep 01 21:22:36 volumio go-librespot[1170]: /src/dealer/dealer.go:125 +0x98 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 102 gp=0x2d14a28 m=nil [runnable]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c46e98 sp=0x2c46e84 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x2c46fd4, 0x2c46f60, 0x0, 0x0, 0x2, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x2c46f38 sp=0x2c46e98 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/dealer.(*Dealer).pingTicker(0x2d74168) Sep 01 21:22:36 volumio go-librespot[1170]: /src/dealer/dealer.go:138 +0x8c fp=0x2c46fe4 sp=0x2c46f38 pc=0x52616c Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/dealer.(*Dealer).ReceiveMessage.(*Dealer).startReceiving.func1.gowrap2() Sep 01 21:22:36 volumio go-librespot[1170]: /src/dealer/dealer.go:129 +0x28 fp=0x2c46fec sp=0x2c46fe4 pc=0x528078 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c46fec sp=0x2c46fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by github.com/devgianlu/go-librespot/dealer.(*Dealer).ReceiveMessage.(*Dealer).startReceiving.func1 in goroutine 11 Sep 01 21:22:36 volumio go-librespot[1170]: /src/dealer/dealer.go:129 +0x15c Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 93 gp=0x30c5688 m=nil [runnable]: Sep 01 21:22:36 volumio go-librespot[1170]: syscall.Syscall(0x3, 0xc, 0x2fd2000, 0x1000) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/syscall/syscall_linux.go:69 +0x8 fp=0x3020aec sp=0x3020ab4 pc=0xa845c Sep 01 21:22:36 volumio go-librespot[1170]: syscall.read(0xc, {0x2fd2000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/syscall/zsyscall_linux_arm.go:736 +0x48 fp=0x3020b14 sp=0x3020aec pc=0xa62e0 Sep 01 21:22:36 volumio go-librespot[1170]: syscall.Read(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/syscall/syscall_unix.go:181 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.ignoringEINTRIO(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:736 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Read(0x2f1fd60, {0x2fd2000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:160 +0x270 fp=0x3020b5c sp=0x3020b14 pc=0x10b444 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).Read(0x2f1fd60, {0x2fd2000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_posix.go:55 +0x38 fp=0x3020b88 sp=0x3020b5c pc=0x17c4d8 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*conn).Read(0x2d00d38, {0x2fd2000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/net.go:179 +0x48 fp=0x3020bb4 sp=0x3020b88 pc=0x18c9f4 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPConn).Read(0x2d00d38, {0x2fd2000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x44 fp=0x3020bd4 sp=0x3020bb4 pc=0x19fc48 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*atLeastReader).Read(0x2c901a0, {0x2fd2000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:806 +0x78 fp=0x3020c00 sp=0x3020bd4 pc=0x27c588 Sep 01 21:22:36 volumio go-librespot[1170]: bytes.(*Buffer).ReadFrom(0x2d7bc8c, {0x84ed44, 0x2c901a0}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bytes/buffer.go:211 +0xa4 fp=0x3020c3c sp=0x3020c00 pc=0x139ad8 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readFromUntil(0x2d7bb08, {0x84df04, 0x2d00d38}, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:828 +0xd4 fp=0x3020c64 sp=0x3020c3c pc=0x27c7e4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecordOrCCS(0x2d7bb08, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:626 +0x134 fp=0x3020dc8 sp=0x3020c64 pc=0x279ee4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecord(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:588 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).Read(0x2d7bb08, {0x2fd8000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:1370 +0x15c fp=0x3020df8 sp=0x3020dc8 pc=0x27fd54 Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).Read(0x2fb3830, {0x2cbe824, 0x9, 0x9}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:241 +0x214 fp=0x3020e1c sp=0x3020df8 pc=0x2be348 Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category user_interface Sep 01 21:22:36 volumio volumio[2811]: info: Scanning into folder /data/plugins/ Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category audio_interface Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category music_service Sep 01 21:22:36 volumio volumio[2811]: info: Scanning category user_interface Sep 01 21:22:36 volumio volumio[2811]: info: Plugin folders cleanup completed Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadAtLeast({0x84e0f8, 0x2fb3830}, {0x2cbe824, 0x9, 0x9}, 0x9) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:335 +0x90 fp=0x3020e48 sp=0x3020e1c pc=0x1041c8 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadFull(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:354 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.http2readFrameHeader({0x2cbe824, 0x9, 0x9}, {0x84e0f8, 0x2fb3830}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:1638 +0x54 fp=0x3020e70 sp=0x3020e48 pc=0x2f7244 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Framer).ReadFrame(0x2cbe800) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:1902 +0x88 fp=0x3020eec sp=0x3020e70 pc=0x2f79dc Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2clientConnReadLoop).run(0x3020fdc) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:9334 +0x150 fp=0x3020fa4 sp=0x3020eec pc=0x31c1f8 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2ClientConn).readLoop(0x2cb2608) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:9229 +0x68 fp=0x3020fe4 sp=0x3020fa4 pc=0x31b6ec Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Transport).newClientConn.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7879 +0x28 fp=0x3020fec sp=0x3020fe4 pc=0x314738 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x3020fec sp=0x3020fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*http2Transport).newClientConn in goroutine 92 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7879 +0xcb0 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 133 gp=0x2d14d88 m=nil [IO wait]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605d928, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x2c55ad4 sp=0x2c55ac0 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605d918, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x2c55aec sp=0x2c55ad4 pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605d918, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x2c55b00 sp=0x2c55aec pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2d06ba8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x2c55b14 sp=0x2c55b00 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Read(0x2d06b90, {0x30a6000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:164 +0x238 fp=0x2c55b5c sp=0x2c55b14 pc=0x10b40c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).Read(0x2d06b90, {0x30a6000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_posix.go:55 +0x38 fp=0x2c55b88 sp=0x2c55b5c pc=0x17c4d8 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*conn).Read(0x2c30640, {0x30a6000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/net.go:179 +0x48 fp=0x2c55bb4 sp=0x2c55b88 pc=0x18c9f4 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPConn).Read(0x2c30640, {0x30a6000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x44 fp=0x2c55bd4 sp=0x2c55bb4 pc=0x19fc48 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*atLeastReader).Read(0x2ed8080, {0x30a6000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:806 +0x78 fp=0x2c55c00 sp=0x2c55bd4 pc=0x27c588 Sep 01 21:22:36 volumio go-librespot[1170]: bytes.(*Buffer).ReadFrom(0x2fe738c, {0x84ed44, 0x2ed8080}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bytes/buffer.go:211 +0xa4 fp=0x2c55c3c sp=0x2c55c00 pc=0x139ad8 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readFromUntil(0x2fe7208, {0x84df04, 0x2c30640}, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:828 +0xd4 fp=0x2c55c64 sp=0x2c55c3c pc=0x27c7e4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecordOrCCS(0x2fe7208, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:626 +0x134 fp=0x2c55dc8 sp=0x2c55c64 pc=0x279ee4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecord(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:588 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).Read(0x2fe7208, {0x30b2000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:1370 +0x15c fp=0x2c55df8 sp=0x2c55dc8 pc=0x27fd54 Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).Read(0x30a4c60, {0x2cbf224, 0x9, 0x9}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:241 +0x214 fp=0x2c55e1c sp=0x2c55df8 pc=0x2be348 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadAtLeast({0x84e0f8, 0x30a4c60}, {0x2cbf224, 0x9, 0x9}, 0x9) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:335 +0x90 fp=0x2c55e48 sp=0x2c55e1c pc=0x1041c8 Sep 01 21:22:36 volumio go-librespot[1170]: io.ReadFull(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/io/io.go:354 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.http2readFrameHeader({0x2cbf224, 0x9, 0x9}, {0x84e0f8, 0x30a4c60}) Sep 01 21:22:36 volumio volumio[2811]: info: ------------------------------------------- Sep 01 21:22:36 volumio volumio[2811]: info: ----- Core plugins startup ---- Sep 01 21:22:36 volumio volumio[2811]: info: ------------------------------------------- Sep 01 21:22:36 volumio volumio[2811]: info: Loading plugins from folder /volumio/app/plugins/ Sep 01 21:22:36 volumio volumio[2811]: info: Adding plugin upnp to MyMusic Plugins Sep 01 21:22:36 volumio volumio[2811]: info: Adding plugin airplay_emulation to MyMusic Plugins Sep 01 21:22:36 volumio volumio[2811]: info: Adding plugin upnp_browser to MyMusic Plugins Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:1638 +0x54 fp=0x2c55e70 sp=0x2c55e48 pc=0x2f7244 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Framer).ReadFrame(0x2cbf200) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:1902 +0x88 fp=0x2c55eec sp=0x2c55e70 pc=0x2f79dc Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2clientConnReadLoop).run(0x2c55fdc) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:9334 +0x150 fp=0x2c55fa4 sp=0x2c55eec pc=0x31c1f8 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2ClientConn).readLoop(0x2cb2708) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:9229 +0x68 fp=0x2c55fe4 sp=0x2c55fa4 pc=0x31b6ec Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Transport).newClientConn.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7879 +0x28 fp=0x2c55fec sp=0x2c55fe4 pc=0x314738 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x2c55fec sp=0x2c55fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*http2Transport).newClientConn in goroutine 132 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7879 +0xcb0 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 158 gp=0x2fea5a8 m=nil [select]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x3023df4 sp=0x3023de0 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x3023f30, 0x3023ebc, 0x0, 0x0, 0x6, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x3023e94 sp=0x3023df4 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2clientStream).writeRequest(0x2f20708, 0x2fcc828) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:8522 +0xa90 fp=0x3023fcc sp=0x3023e94 pc=0x317ca4 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2clientStream).doRequest(0x2f20708, 0x2fcc828) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:8384 +0x24 fp=0x3023fe0 sp=0x3023fcc pc=0x3171e8 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2ClientConn).RoundTrip.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:8290 +0x30 fp=0x3023fec sp=0x3023fe0 pc=0x317198 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x3023fec sp=0x3023fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*http2ClientConn).RoundTrip in goroutine 157 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:8290 +0x338 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 156 gp=0x30c59e8 m=nil [select]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x301eeb0 sp=0x301ee9c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x301efac, 0x301ef78, 0x0, 0x0, 0x2, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x301ef50 sp=0x301eeb0 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*persistConn).writeLoop(0x2cea168) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:2444 +0xd0 fp=0x301efe4 sp=0x301ef50 pc=0x357b24 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Transport).dialConn.gowrap3() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1800 +0x28 fp=0x301efec sp=0x301efe4 pc=0x354930 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x301efec sp=0x301efec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*Transport).dialConn in goroutine 126 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1800 +0x1444 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 155 gp=0x2feac68 m=nil [IO wait]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa4c, 0x7605d6a8, 0x2, 0x2, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x3037afc sp=0x3037ae8 pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.netpollblock(0x7605d698, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:573 +0x100 fp=0x3037b14 sp=0x3037afc pc=0x547d4 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.runtime_pollWait(0x7605d698, 0x72) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/netpoll.go:345 +0x54 fp=0x3037b28 sp=0x3037b14 pc=0x8f3b0 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).wait(0x2f1fdc8, 0x72, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x3037b3c sp=0x3037b28 pc=0x10a220 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*pollDesc).waitRead(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_poll_runtime.go:89 Sep 01 21:22:36 volumio go-librespot[1170]: internal/poll.(*FD).Read(0x2f1fdb0, {0x2e4e000, 0xc000, 0xc000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/internal/poll/fd_unix.go:164 +0x238 fp=0x3037b84 sp=0x3037b3c pc=0x10b40c Sep 01 21:22:36 volumio go-librespot[1170]: net.(*netFD).Read(0x2f1fdb0, {0x2e4e000, 0xc000, 0xc000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/fd_posix.go:55 +0x38 fp=0x3037bb0 sp=0x3037b84 pc=0x17c4d8 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*conn).Read(0x2c30140, {0x2e4e000, 0xc000, 0xc000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/net.go:179 +0x48 fp=0x3037bdc sp=0x3037bb0 pc=0x18c9f4 Sep 01 21:22:36 volumio go-librespot[1170]: net.(*TCPConn).Read(0x2c30140, {0x2e4e000, 0xc000, 0xc000}) Sep 01 21:22:36 volumio go-librespot[1170]: :1 +0x44 fp=0x3037bfc sp=0x3037bdc pc=0x19fc48 Sep 01 21:22:36 volumio volumio[2811]: info: Loading plugins from folder /data/plugins/ Sep 01 21:22:36 volumio volumio[2811]: info: Loading plugin "system"... Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*atLeastReader).Read(0x3097ba0, {0x2e4e000, 0xc000, 0xc000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:806 +0x78 fp=0x3037c28 sp=0x3037bfc pc=0x27c588 Sep 01 21:22:36 volumio go-librespot[1170]: bytes.(*Buffer).ReadFrom(0x2fe684c, {0x84ed44, 0x3097ba0}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bytes/buffer.go:211 +0xa4 fp=0x3037c64 sp=0x3037c28 pc=0x139ad8 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readFromUntil(0x2fe66c8, {0x84df04, 0x2c30140}, 0x5) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:828 +0xd4 fp=0x3037c8c sp=0x3037c64 pc=0x27c7e4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecordOrCCS(0x2fe66c8, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:626 +0x134 fp=0x3037df0 sp=0x3037c8c pc=0x279ee4 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).readRecord(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:588 Sep 01 21:22:36 volumio go-librespot[1170]: crypto/tls.(*Conn).Read(0x2fe66c8, {0x2faa000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/crypto/tls/conn.go:1370 +0x15c fp=0x3037e20 sp=0x3037df0 pc=0x27fd54 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*persistConn).Read(0x2cea168, {0x2faa000, 0x1000, 0x1000}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1977 +0x16c fp=0x3037e54 sp=0x3037e20 pc=0x3554d4 Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).fill(0x30043c0) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:110 +0x10c fp=0x3037e78 sp=0x3037e54 pc=0x2bdcbc Sep 01 21:22:36 volumio go-librespot[1170]: bufio.(*Reader).Peek(0x30043c0, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/bufio/bufio.go:148 +0x68 fp=0x3037e84 sp=0x3037e78 pc=0x2bde40 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*persistConn).readLoop(0x2cea168) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:2141 +0x194 fp=0x3037fe4 sp=0x3037e84 pc=0x356064 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Transport).dialConn.gowrap2() Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1799 +0x28 fp=0x3037fec sp=0x3037fe4 pc=0x354984 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x3037fec sp=0x3037fec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by net/http.(*Transport).dialConn in goroutine 126 Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:1799 +0x13f4 Sep 01 21:22:36 volumio go-librespot[1170]: goroutine 157 gp=0x2feb8c8 m=nil [select]: Sep 01 21:22:36 volumio go-librespot[1170]: runtime.gopark(0x7afa90, 0x0, 0x9, 0x3, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/proc.go:402 +0x104 fp=0x303b440 sp=0x303b42c pc=0x5cfc8 Sep 01 21:22:36 volumio go-librespot[1170]: runtime.selectgo(0x303b54c, 0x303b504, 0x0, 0x0, 0x4, 0x1) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/select.go:327 +0xaf0 fp=0x303b4e0 sp=0x303b440 pc=0x70d80 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2ClientConn).RoundTrip(0x2cb2608, 0x2fcc828) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:8354 +0x430 fp=0x303b590 sp=0x303b4e0 pc=0x316c24 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Transport).RoundTripOpt(0x2d48a20, 0x2fcc828, {0x0}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7622 +0x208 fp=0x303b62c sp=0x303b590 pc=0x3129e8 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*http2Transport).RoundTrip(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:7571 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.http2noDialH2RoundTripper.RoundTrip({0x2d48a20}, 0x2fcc828) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/h2_bundle.go:10198 +0x30 fp=0x303b654 sp=0x303b62c pc=0x3211a0 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Transport).roundTrip(0xc6b258, 0x2fcc828) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/transport.go:553 +0x3c4 fp=0x303b770 sp=0x303b654 pc=0x34d1a4 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Transport).RoundTrip(0xc6b258, 0x2fcc828) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/roundtrip.go:17 +0x24 fp=0x303b788 sp=0x303b770 pc=0x331974 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.send(0x2fcc6e8, {0x84e274, 0xc6b258}, {0xc2259702ab93105b, 0x93bb8ca214, 0xcc6880}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/client.go:259 +0x540 fp=0x303b8b4 sp=0x303b788 pc=0x2ec69c Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Client).send(0x2d033a0, 0x2fcc6e8, {0xc2259702ab93105b, 0x93bb8ca214, 0xcc6880}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/client.go:180 +0x98 fp=0x303b8f8 sp=0x303b8b4 pc=0x2ebf90 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Client).do(0x2d033a0, 0x2fcc6e8) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/client.go:724 +0x8bc fp=0x303ba08 sp=0x303b8f8 pc=0x2ee390 Sep 01 21:22:36 volumio go-librespot[1170]: net/http.(*Client).Do(...) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/net/http/client.go:590 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/spclient.(*Spclient).innerRequest.func2() Sep 01 21:22:36 volumio go-librespot[1170]: /src/spclient/spclient.go:94 +0x308 fp=0x303ba68 sp=0x303ba08 pc=0x4f70c8 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/cenkalti/backoff/v4.doRetryNotify[...](0x303bbf0, {0x74ef7520, 0x2c90120}, 0x0, {0x0, 0x0}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:88 +0xf0 fp=0x303bae8 sp=0x303ba68 pc=0x4932ec Sep 01 21:22:36 volumio go-librespot[1170]: github.com/cenkalti/backoff/v4.RetryNotifyWithData[...](...) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:54 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/cenkalti/backoff/v4.RetryWithData[...](0x303bbf0, {0x74ef7520, 0x2c90120}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/.gocache/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:43 +0x54 fp=0x303bb14 sp=0x303bae8 pc=0x4931d4 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/spclient.(*Spclient).innerRequest(0x2d792f0, {0x852ad0, 0xcf1518}, {0x782181, 0x3}, 0x2ca20a0, 0x0, 0x0, {0x0, 0x0, ...}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/spclient/spclient.go:84 +0x3cc fp=0x303bc50 sp=0x303bb14 pc=0x4f6c24 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/spclient.(*Spclient).Request(0x2d792f0, {0x852ad0, 0xcf1518}, {0x782181, 0x3}, {0x2cb6c60, 0x51}, 0x0, 0x0, {0x0, ...}) Sep 01 21:22:36 volumio go-librespot[1170]: /src/spclient/spclient.go:122 +0xb0 fp=0x303bc94 sp=0x303bc50 pc=0x4f750c Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/spclient.(*Spclient).ResolveStorageInteractive(0x2d792f0, {0x852ad0, 0xcf1518}, {0x2c2a528, 0x14, 0x18}, 0x0) Sep 01 21:22:36 volumio go-librespot[1170]: /src/spclient/spclient.go:204 +0x1e8 fp=0x303bd14 sp=0x303bc94 pc=0x4f8634 Sep 01 21:22:36 volumio go-librespot[1170]: github.com/devgianlu/go-librespot/player.(*Player).NewStream(0x2f1f220, {0x852ad0, 0xcf1518}, 0x2d033a0, {{0x2d25748, 0x5}, {0x2eea4c0, 0x10, 0x10}}, 0x140, ...) Sep 01 21:22:36 volumio go-librespot[1170]: /src/player/player.go:523 +0x738 fp=0x303be8c sp=0x303bd14 pc=0x509e28 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*AppPlayer).prefetchNext(0x3030230) Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/controls.go:48 +0x254 fp=0x303bfe4 sp=0x303be8c pc=0x629954 Sep 01 21:22:36 volumio go-librespot[1170]: main.(*AppPlayer).schedulePrefetchNext.gowrap1() Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/controls.go:72 +0x28 fp=0x303bfec sp=0x303bfe4 pc=0x62a3fc Sep 01 21:22:36 volumio go-librespot[1170]: runtime.goexit({}) Sep 01 21:22:36 volumio go-librespot[1170]: /usr/local/go/src/runtime/asm_arm.s:859 +0x4 fp=0x303bfec sp=0x303bfec pc=0x93c74 Sep 01 21:22:36 volumio go-librespot[1170]: created by main.(*AppPlayer).schedulePrefetchNext in goroutine 11 Sep 01 21:22:36 volumio go-librespot[1170]: /src/cmd/daemon/controls.go:72 +0x1c8 Sep 01 21:22:36 volumio go-librespot[1170]: Aborted Sep 01 21:22:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Sep 01 21:22:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 01 21:22:37 volumio volumio[2811]: info: Loading plugin "appearance"... Sep 01 21:22:38 volumio volumio[2811]: info: Loading plugin "network"... Sep 01 21:22:38 volumio volumio[2811]: info: Refreshing Cached IP Addresses Sep 01 21:22:38 volumio sudo[2841]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 21:22:38 volumio sudo[2841]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:22:38 volumio sudo[2843]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 21:22:38 volumio sudo[2843]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:22:38 volumio sudo[2843]: pam_unix(sudo:session): session closed for user root Sep 01 21:22:38 volumio volumio[2811]: info: Loading plugin "services"... Sep 01 21:22:38 volumio sudo[2841]: pam_unix(sudo:session): session closed for user root Sep 01 21:22:38 volumio volumio[2811]: info: Loading plugin "alsa_controller"... Sep 01 21:22:38 volumio sudo[2854]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 01 21:22:38 volumio sudo[2854]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:22:38 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 21:22:38 volumio volumio[2811]: info: Loading plugin "wizard"... Sep 01 21:22:38 volumio volumio[2811]: info: Loading plugin "networkfs"... Sep 01 21:22:38 volumio volumio[2811]: info: Starting Udev Watcher for removable devices Sep 01 21:22:38 volumio volumio[2811]: info: Ignoring mount for partition: boot Sep 01 21:22:38 volumio volumio[2811]: info: Ignoring mount for partition: volumio Sep 01 21:22:38 volumio volumio[2811]: info: Ignoring mount for partition: volumio_data Sep 01 21:22:38 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 21:22:38 volumio volumio[2811]: info: Loading plugin "volumio_command_line_client"... Sep 01 21:22:39 volumio volumio[2811]: info: Loading plugin "upnp"... Sep 01 21:22:39 volumio volumio[2811]: info: [1756750959021] Starting Upmpd Daemon Sep 01 21:22:39 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 21:22:39 volumio volumio[2811]: info: Loading plugin "my_music"... Sep 01 21:22:39 volumio volumio[2811]: info: Loading plugin "mpd"... Sep 01 21:22:39 volumio volumio[2811]: info: Loading plugin "upnp_browser"... Sep 01 21:22:39 volumio sudo[2854]: pam_unix(sudo:session): session closed for user root Sep 01 21:22:40 volumio volumio[2811]: info: Loading plugin "alarm-clock"... Sep 01 21:22:40 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 01 21:22:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Sep 01 21:22:40 volumio systemd[1]: Stopped go-librespot Daemon. Sep 01 21:22:40 volumio systemd[1]: Started go-librespot Daemon. Sep 01 21:22:40 volumio go-librespot[2868]: go-librespot daemon starting... Sep 01 21:22:40 volumio go-librespot[2868]: time="2025-09-01T21:22:40+03:00" level=info msg="running go-librespot 0.3.2" Sep 01 21:22:40 volumio go-librespot[2868]: time="2025-09-01T21:22:40+03:00" level=debug msg="app state loaded" Sep 01 21:22:40 volumio go-librespot[2868]: time="2025-09-01T21:22:40+03:00" level=debug msg="stored credentials not found" Sep 01 21:22:40 volumio go-librespot[2868]: time="2025-09-01T21:22:40+03:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 21:22:40 volumio volumio[2811]: info: Loading plugin "airplay_emulation"... Sep 01 21:22:40 volumio volumio[2811]: info: Starting Shairport Sync Sep 01 21:22:40 volumio volumio[2811]: info: Loading plugin "last_100"... Sep 01 21:22:40 volumio volumio[2811]: info: Loading plugin "webradio"... Sep 01 21:22:40 volumio volumio[2811]: info: Loading plugin "i2s_dacs"... Sep 01 21:22:40 volumio volumio[2811]: info: Loading plugin "volumiodiscovery"... Sep 01 21:22:40 volumio go-librespot[2868]: time="2025-09-01T21:22:40+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Sep 01 21:22:40 volumio go-librespot[2868]: time="2025-09-01T21:22:40+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 01 21:22:40 volumio go-librespot[2868]: time="2025-09-01T21:22:40+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 01 21:22:40 volumio go-librespot[2868]: time="2025-09-01T21:22:40+03:00" level=info msg="zeroconf server listening on port 34319" Sep 01 21:22:40 volumio volumio[2811]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 21:22:40 volumio volumio[2811]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 21:22:40 volumio volumio[2811]: *** WARNING *** For more information see Sep 01 21:22:40 volumio node[2811]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 01 21:22:40 volumio volumio[2811]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 21:22:40 volumio volumio[2811]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 21:22:40 volumio volumio[2811]: *** WARNING *** For more information see Sep 01 21:22:40 volumio node[2811]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 21:22:40 volumio node[2811]: *** WARNING *** For more information see Sep 01 21:22:40 volumio node[2811]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 01 21:22:40 volumio node[2811]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 01 21:22:40 volumio node[2811]: *** WARNING *** For more information see Sep 01 21:22:40 volumio volumio[2811]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 01 21:22:40 volumio volumio[2811]: info: Discovery: Started advertising with name: Volumio Sep 01 21:22:40 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 01 21:22:40 volumio volumio[2811]: info: Loading plugin "spop"... Sep 01 21:22:42 volumio volumio[2811]: info: Loading plugin "youtube2"... Sep 01 21:22:47 volumio volumio[2811]: info: Loading plugin "ytcr"... Sep 01 21:22:48 volumio volumio-remote-updater[465]: [2025-09-01 21:22:48] [connect] Successful connection Sep 01 21:22:54 volumio volumio[2811]: info: Plugin ytmusic is not enabled Sep 01 21:22:54 volumio volumio[2811]: info: Loading plugin "now_playing"... Sep 01 21:22:56 volumio volumio[2811]: info: Loading plugin "outputs"... Sep 01 21:22:56 volumio volumio[2811]: info: Loading plugin "albumart"... Sep 01 21:22:56 volumio volumio[2811]: info: Plugin example_plugin is not enabled Sep 01 21:22:56 volumio volumio[2811]: info: Loading plugin "inputs"... Sep 01 21:22:56 volumio volumio[2811]: info: Loading plugin "updater_comm"... Sep 01 21:22:56 volumio volumio[2811]: info: Plugin mpdemulation is not enabled Sep 01 21:22:56 volumio volumio[2811]: info: Loading plugin "rest_api"... Sep 01 21:22:56 volumio volumio[2811]: info: Loading plugin "websocket"... Sep 01 21:22:56 volumio volumio[2811]: info: Starting Socket.io Server version 2.3.0 Sep 01 21:22:56 volumio volumio[2811]: info: Loading plugin "fusiondsp"... Sep 01 21:22:57 volumio volumio[2811]: Forking 3 albumart workers Sep 01 21:22:57 volumio volumio[2811]: info: Applying required configuration parameters for plugin fusiondsp Sep 01 21:22:57 volumio volumio[2811]: info: Loading plugin "mpdoutput"... Sep 01 21:22:58 volumio volumio[2811]: info: Loading plugin "minidlna"... Sep 01 21:22:58 volumio volumio[2811]: Starting albumart workers Sep 01 21:22:58 volumio volumio[2811]: Starting albumart workers Sep 01 21:22:58 volumio volumio[2811]: info: Applying required configuration parameters for plugin minidlna Sep 01 21:22:58 volumio volumio[2811]: Starting albumart workers Sep 01 21:22:58 volumio volumio[2811]: info: Loading i18n strings for locale en Sep 01 21:22:58 volumio volumio[2811]: info: Plugin mpdoutput has duplicated i18n key SAVE. It is ignored. Sep 01 21:22:58 volumio volumio[2811]: Updating browse sources language Sep 01 21:22:58 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::initPlayerControls Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: Express server listening on port 3000 Sep 01 21:22:59 volumio volumio[2811]: [Metrics] WebUI: 24s 989.42ms Sep 01 21:22:59 volumio volumio[2811]: info: CoreStateMachine::resetVolumioState Sep 01 21:22:59 volumio volumio[2811]: info: CoreStateMachine::getcurrentVolume Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 21:22:59 volumio volumio[2811]: info: CoreStateMachine::pushState Sep 01 21:22:59 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::volumioPushState Sep 01 21:22:59 volumio volumio[2811]: info: Volumio Network Manager: Network status updated: 2 Sep 01 21:22:59 volumio sudo[3003]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 21:22:59 volumio sudo[3009]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 21:22:59 volumio sudo[3003]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:22:59 volumio sudo[3009]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:22:59 volumio sudo[3009]: pam_unix(sudo:session): session closed for user root Sep 01 21:22:59 volumio volumio[2811]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Sep 01 21:22:59 volumio volumio[2811]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Sep 01 21:22:59 volumio volumio[2811]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Sep 01 21:22:59 volumio volumio[2811]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 Sep 01 21:22:59 volumio sudo[3003]: pam_unix(sudo:session): session closed for user root Sep 01 21:22:59 volumio volumio[2811]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Sep 01 21:22:59 volumio volumio[2811]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Sep 01 21:22:59 volumio volumio[2811]: info: Reloading queue from file Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:22:59 volumio volumio[2811]: info: CoreStateMachine::setRepeat null single undefined Sep 01 21:22:59 volumio volumio[2811]: info: CoreStateMachine::pushState Sep 01 21:22:59 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::volumioPushState Sep 01 21:22:59 volumio volumio[2811]: info: CoreStateMachine::setRandom null Sep 01 21:22:59 volumio volumio[2811]: info: CoreStateMachine::pushState Sep 01 21:22:59 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:22:59 volumio volumio[2811]: info: CoreCommandRouter::volumioPushState Sep 01 21:22:59 volumio volumio[2811]: info: Setting Device type: Raspberry PI Sep 01 21:22:59 volumio volumio[2811]: info: Completed loading Core Plugins Sep 01 21:22:59 volumio volumio[2811]: info: Preparing to generate the ALSA configuration file Sep 01 21:22:59 volumio volumio[2811]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Sep 01 21:22:59 volumio volumio[2811]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Sep 01 21:22:59 volumio volumio[2811]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Sep 01 21:22:59 volumio volumio[2811]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Sep 01 21:22:59 volumio volumio[2811]: info: Reading ALSA contributions from plugins. Sep 01 21:22:59 volumio sudo[3020]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Sep 01 21:22:59 volumio sudo[3020]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:22:59 volumio volumio[2811]: info: Asound.conf file unchanged, so no further update is needed Sep 01 21:22:59 volumio volumio[2811]: info: Output device has changed, restarting MPD Sep 01 21:23:00 volumio sudo[3023]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 21:23:00 volumio sudo[3023]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:00 volumio sudo[3023]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:00 volumio volumio[2811]: info: Output device has changed, restarting Shairport Sync Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:00 volumio sudo[3026]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 21:23:00 volumio sudo[3026]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:00 volumio systemd[1]: Stopping Music Player Daemon... Sep 01 21:23:00 volumio sudo[3020]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:00 volumio volumio[2811]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 21:23:00 volumio volumio[2811]: info: ___________ START PLUGINS ___________ Sep 01 21:23:00 volumio volumio[2811]: info: ControllerMpd::onStart: Initializing MPD Sep 01 21:23:00 volumio volumio[2811]: info: Creating MPD Configuration file Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 21:23:00 volumio sudo[3032]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 21:23:00 volumio volumio[2811]: info: [1756750980550] CoreMusicLibrary::Adding element Media Servers Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 21:23:00 volumio sudo[3032]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:00 volumio sudo[3032]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:00 volumio sudo[3034]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 21:23:00 volumio sudo[3034]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 21:23:00 volumio volumio[2811]: info: [1756750980753] CoreMusicLibrary::Adding element Last_100 Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 21:23:00 volumio volumio[2811]: info: [1756750980758] CoreMusicLibrary::Adding element Webradio Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 21:23:00 volumio volumio[2811]: info: Initializing BBC Radios Sep 01 21:23:00 volumio volumio[2811]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: Creating Spotify config file Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 01 21:23:00 volumio volumio[2811]: info: [1756750980944] CoreMusicLibrary::Adding element YouTube2 Sep 01 21:23:00 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 21:23:00 volumio volumio[2811]: Cannot find translation for source YouTube2 Sep 01 21:23:01 volumio volumio[2811]: info: [now-playing] ConfigUpdater: config is up to date. Sep 01 21:23:01 volumio volumio[2811]: info: Loading i18n strings for locale en Sep 01 21:23:01 volumio volumio[2811]: info: Plugin mpdoutput has duplicated i18n key SAVE. It is ignored. Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: FusionDsp - mixtype--------------------- None Sep 01 21:23:01 volumio volumio[2811]: info: Loading i18n strings for locale en Sep 01 21:23:01 volumio volumio[2811]: info: Plugin mpdoutput has duplicated i18n key SAVE. It is ignored. Sep 01 21:23:01 volumio volumio[2811]: info: Volumio Calling Home Sep 01 21:23:01 volumio volumio[2811]: info: Preparing to generate the ALSA configuration file Sep 01 21:23:01 volumio volumio[2811]: info: [now-playing] App is listening on port 4004. Sep 01 21:23:01 volumio volumio[2811]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Sep 01 21:23:01 volumio volumio[2811]: info: Discovery: adding 3b288d2e-1e38-4f15-823f-68d1a4432367 Sep 01 21:23:01 volumio volumio[2811]: info: Discovery: Found device Volumio Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:01 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:01 volumio volumio[2811]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Sep 01 21:23:01 volumio volumio[2811]: info: Reading ALSA contributions from plugins. Sep 01 21:23:01 volumio volumio[2811]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Sep 01 21:23:01 volumio volumio[2811]: info: MPD Permissions set Sep 01 21:23:01 volumio volumio[2811]: info: Upmpdcli Daemon Started Sep 01 21:23:01 volumio volumio[2811]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Sep 01 21:23:01 volumio volumio[2811]: info: Spotify config file written Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:01 volumio sudo[3058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 01 21:23:01 volumio sudo[3058]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:01 volumio systemd[1]: Stopping go-librespot Daemon... Sep 01 21:23:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Sep 01 21:23:01 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Sep 01 21:23:01 volumio systemd[1]: Stopped go-librespot Daemon. Sep 01 21:23:02 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:02 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:02 volumio systemd[1]: Started go-librespot Daemon. Sep 01 21:23:02 volumio go-librespot[3068]: go-librespot daemon starting... Sep 01 21:23:02 volumio sudo[3058]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:02 volumio volumio[2811]: info: No need to fix Spotify hosts Sep 01 21:23:02 volumio go-librespot[3068]: time="2025-09-01T21:23:02+03:00" level=info msg="running go-librespot 0.3.2" Sep 01 21:23:02 volumio go-librespot[3068]: time="2025-09-01T21:23:02+03:00" level=debug msg="app state loaded" Sep 01 21:23:02 volumio go-librespot[3068]: time="2025-09-01T21:23:02+03:00" level=debug msg="stored credentials not found" Sep 01 21:23:02 volumio go-librespot[3068]: time="2025-09-01T21:23:02+03:00" level=info msg="api server listening on 127.0.0.1:9879" Sep 01 21:23:02 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:02 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:02 volumio volumio[2811]: info: Starting Shairport Sync Sep 01 21:23:02 volumio volumio[2811]: info: Starting Shairport Sync Sep 01 21:23:02 volumio volumio[2811]: info: Starting Shairport Sync Sep 01 21:23:03 volumio volumio[2811]: info: Volumio called home Sep 01 21:23:03 volumio sudo[3085]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 01 21:23:03 volumio sudo[3083]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 21:23:03 volumio sudo[3081]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 21:23:03 volumio sudo[3087]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 01 21:23:03 volumio sudo[3083]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:03 volumio sudo[3081]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:03 volumio sudo[3087]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:03 volumio sudo[3080]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 21:23:03 volumio sudo[3085]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:03 volumio sudo[3080]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:03 volumio sudo[3087]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:03 volumio volumio[2811]: /usr/bin/mkfifo: cannot create fifo '/tmp/fusiondspfifo': File exists Sep 01 21:23:03 volumio volumio[2811]: error: FusionDsp - ----failed to create fusiondspfifo :Error: Command failed: /bin/touch /tmp/fusiondsp_stream_params.log && /bin/chmod 666 /tmp/fusiondsp_stream_params.log && /bin/touch /tmp/camilladsp.log && /bin/chmod 666 /tmp/camilladsp.log && /usr/bin/mkfifo -m 646 /tmp/fusiondspfifo Sep 01 21:23:03 volumio volumio[2811]: /usr/bin/mkfifo: cannot create fifo '/tmp/fusiondspfifo': File exists Sep 01 21:23:03 volumio volumio[2811]: info: camilladsp service started and running in background, instance 1 Sep 01 21:23:03 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:03 volumio sudo[3085]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:03 volumio volumio-remote-updater[465]: [2025-09-01 21:23:03] [connect] Successful connection Sep 01 21:23:03 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Sep 01 21:23:03 volumio systemd[1]: shairport-sync.service: Succeeded. Sep 01 21:23:03 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Sep 01 21:23:03 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Sep 01 21:23:03 volumio sudo[3081]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:03 volumio sudo[3083]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:03 volumio sudo[3080]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:03 volumio go-librespot[3068]: time="2025-09-01T21:23:03+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 01 21:23:03 volumio go-librespot[3068]: time="2025-09-01T21:23:03+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 01 21:23:03 volumio go-librespot[3068]: time="2025-09-01T21:23:03+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 01 21:23:03 volumio volumio[2811]: cannot open device 'volumioHw': Device or resource busy Sep 01 21:23:04 volumio volumio[2811]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json Sep 01 21:23:04 volumio volumio[2811]: cannot open device 'volumioHw': Device or resource busy Sep 01 21:23:04 volumio go-librespot[3068]: time="2025-09-01T21:23:03+03:00" level=info msg="zeroconf server listening on port 35253" Sep 01 21:23:04 volumio volumio[2811]: info: FusionDsp loaded Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 21:23:04 volumio sudo[3117]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Sep 01 21:23:04 volumio sudo[3117]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:04 volumio volumio[2811]: info: FusionDsp - Reporting Fusion DSP Enabled Sep 01 21:23:04 volumio volumio[2811]: info: Adding Signal Path Element [object Object] Sep 01 21:23:04 volumio volumio[2811]: info: Adding fusiondspeq DSP Signal Path Element Sep 01 21:23:04 volumio volumio[2811]: info: FusionDsp - ---- installed callbackRead Sep 01 21:23:04 volumio volumio[2811]: info: Asound.conf file unchanged, so no further update is needed Sep 01 21:23:04 volumio volumio[2811]: info: Output device has changed, restarting MPD Sep 01 21:23:04 volumio sudo[3117]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:04 volumio systemd[1]: mpd.service: Succeeded. Sep 01 21:23:04 volumio systemd[1]: Stopped Music Player Daemon. Sep 01 21:23:04 volumio sudo[3120]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 01 21:23:04 volumio sudo[3120]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:04 volumio volumio[2811]: info: Output device has changed, restarting Shairport Sync Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:04 volumio sudo[3120]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:04 volumio sudo[3124]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 21:23:04 volumio sudo[3124]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:04 volumio systemd[1]: Starting Music Player Daemon... Sep 01 21:23:04 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Sep 01 21:23:04 volumio systemd[1]: mpd.service: Succeeded. Sep 01 21:23:04 volumio systemd[1]: Stopped Music Player Daemon. Sep 01 21:23:04 volumio volumio[2811]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 01 21:23:04 volumio systemd[1]: Starting Music Player Daemon... Sep 01 21:23:04 volumio volumio[2811]: info: Shairport-Sync Started Sep 01 21:23:04 volumio volumio[2811]: Error adding Membership: Error: addMembership EINVAL Sep 01 21:23:04 volumio volumio[2811]: info: Shairport-Sync Started Sep 01 21:23:04 volumio volumio[2811]: info: Shairport-Sync Started Sep 01 21:23:04 volumio volumio[2811]: info: FusionDsp - If filter freq >samplerate/2 then disable it Sep 01 21:23:04 volumio volumio[2811]: verbose: New Socket.io Connection to 192.168.137.10 from 192.168.137.1 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Sep 01 21:23:04 volumio volumio-remote-updater[465]: [2025-09-01 21:23:04] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1756750983 101 Sep 01 21:23:04 volumio volumio[2811]: 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: 10 Sep 01 21:23:04 volumio volumio[2811]: info: MPD Permissions set Sep 01 21:23:04 volumio volumio[2811]: info: minidlna: Found miniDLNA version 1.2.1 Sep 01 21:23:04 volumio volumio[2811]: info: minidlna: Starting minidlna.service Sep 01 21:23:04 volumio sudo[3130]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 01 21:23:04 volumio sudo[3130]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:04 volumio sudo[3130]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 01 21:23:04 volumio sudo[3135]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start minidlna.service Sep 01 21:23:04 volumio sudo[3135]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:04 volumio volumio[2811]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::volumioGetVisibleSources Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:04 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 01 21:23:04 volumio sudo[3135]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:04 volumio volumio[2811]: info: Received Get System Info Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 21:23:04 volumio volumio[2811]: info: Discovery: Getting this device information Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:04 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:04 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:04 volumio volumio[2811]: info: Listing playlists Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 01 21:23:04 volumio volumio[2811]: info: FusionDsp - {"Reload":{"result":"Ok"}} Sep 01 21:23:04 volumio volumio[2811]: info: minidlna: systemctl start minidlna.service succeeded. Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:04 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::volumioPause Sep 01 21:23:04 volumio volumio[2811]: info: CoreStateMachine::pause Sep 01 21:23:04 volumio volumio[2811]: info: mpdhttpout --- Volumio set on pause Sep 01 21:23:04 volumio volumio[2811]: info: mpdhttpout ---Configuration successfully added to mpd.conf. Sep 01 21:23:04 volumio volumio[2811]: info: Starting Shairport Sync Sep 01 21:23:04 volumio sudo[3143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Sep 01 21:23:04 volumio sudo[3143]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:04 volumio volumio[2811]: info: Received Get System Info Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 21:23:04 volumio volumio[2811]: info: Discovery: Getting this device information Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:04 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 21:23:04 volumio volumio[2811]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 01 21:23:04 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Sep 01 21:23:04 volumio systemd[1]: shairport-sync.service: Succeeded. Sep 01 21:23:04 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Sep 01 21:23:04 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Sep 01 21:23:04 volumio sudo[3143]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:04 volumio volumio[2811]: info: FusionDsp - Sep 01 21:23:05 volumio volumio[2811]: info: FusionDsp - undefined Sep 01 21:23:05 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:05 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:05 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Sep 01 21:23:05 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 01 21:23:05 volumio volumio[2811]: info: Received Get System Info Sep 01 21:23:05 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 01 21:23:05 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 01 21:23:05 volumio volumio[2811]: info: Discovery: Getting this device information Sep 01 21:23:05 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:05 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:05 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 01 21:23:05 volumio volumio[2811]: info: Shairport-Sync Started Sep 01 21:23:05 volumio volumio[2811]: info: go-librespot daemon successfully initialized Sep 01 21:23:06 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Sep 01 21:23:06 volumio go-librespot[3068]: time="2025-09-01T21:23:06+03:00" level=debug msg="obtained new client token: AACa8PJFZCw8bBgnKdvRMG6tzM7Qgo90eLukQ+Ln7L39sUBbFA0Vhc9OWhMoRNVZ2uI1lrJgnmSaEGynMFCDM/QMbx3U0lqsKbvqw268K581B3YkD76jmNRTGU0vQH7W4KllV86DvoVHvmpklKN6jraodN1nnZPm1TT2IK9MApCP3q7VnLItqZH6AP8Z3aTg37n19rj+b15LBohRNPM3Mr05Kd7VxovLhQ71b3+frECUE4/5LXfA9iPKxCE=" Sep 01 21:23:06 volumio go-librespot[3068]: time="2025-09-01T21:23:06+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Sep 01 21:23:06 volumio volumio[2811]: info: [yt-cast-receiver] DIAL server listening on port 8098 Sep 01 21:23:06 volumio volumio[2811]: info: CoreCommandRouter::volumioRetrievevolume Sep 01 21:23:06 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:06 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:06 volumio volumio[2811]: info: CoreStateMachine::pushState Sep 01 21:23:06 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:06 volumio volumio[2811]: info: CoreCommandRouter::volumioPushState Sep 01 21:23:06 volumio volumio[2811]: error: [ytcr] VolumeControl failed to obtain volume from Volumio: Sep 01 21:23:06 volumio volumio[2811]: (TypeError) Cannot read property 'vol' of undefined Sep 01 21:23:06 volumio volumio[2811]: TypeError: Cannot read property 'vol' of undefined Sep 01 21:23:06 volumio volumio[2811]: at VolumeControl.getVolume (/data/plugins/music_service/ytcr/dist/lib/VolumeControl.js:56:42) Sep 01 21:23:06 volumio volumio[2811]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Sep 01 21:23:06 volumio volumio[2811]: at async VolumeControl.init (/data/plugins/music_service/ytcr/dist/lib/VolumeControl.js:28:68) Sep 01 21:23:06 volumio volumio[2811]: at async /data/plugins/music_service/ytcr/dist/index.js:326:13 Sep 01 21:23:06 volumio go-librespot[3068]: time="2025-09-01T21:23:06+03:00" level=debug msg="completed keyexchange" Sep 01 21:23:06 volumio go-librespot[3068]: time="2025-09-01T21:23:06+03:00" level=debug msg="completed challenge" Sep 01 21:23:06 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Sep 01 21:23:06 volumio go-librespot[3068]: time="2025-09-01T21:23:06+03:00" level=info msg="authenticated AP" username="a9*********************d3" Sep 01 21:23:06 volumio volumio[2811]: info: CoreCommandRouter::executeOnPlugin: mpd , restartMpd Sep 01 21:23:06 volumio go-librespot[3068]: time="2025-09-01T21:23:06+03:00" level=info msg="authenticated Login5" username="a9*********************d3" Sep 01 21:23:06 volumio go-librespot[3068]: time="2025-09-01T21:23:06+03:00" level=info msg="accepted zeroconf from ה-אברהם של S25 Ultra" username="a9*********************d3" Sep 01 21:23:06 volumio sudo[3150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 01 21:23:06 volumio sudo[3150]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:07 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Sep 01 21:23:07 volumio systemd[1]: mpd.service: Succeeded. Sep 01 21:23:07 volumio systemd[1]: Stopped Music Player Daemon. Sep 01 21:23:07 volumio systemd[1]: Starting Music Player Daemon... Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="dealer connection opened" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=trace msg="starting accesspoint recv loop" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=trace msg="starting dealer recv loop" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=trace msg="received accesspoint ping" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="received connection id: ZDhmYTAxYTEtODYw...RDIyMTBDODYwNQ==" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=trace msg="received accesspoint pong ack" Sep 01 21:23:07 volumio sudo[3152]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 01 21:23:07 volumio sudo[3152]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 01 21:23:07 volumio sudo[3152]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="put connect state because NEW_DEVICE" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="update volume requested to 65535/65535" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=trace msg="emitting websocket event: volume" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="handling transfer player command from 6e0b5ef165abb2750a1beeb6c82440ccdf5e737d" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="resolved context of track" uri="spotify:album:2rJ1Vr7wZKBQ3QvUSzNgXF" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:album:2rJ1Vr7wZKBQ3QvUSzNgXF" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="loading track (paused: false, position: 23001ms)" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=trace msg="emitting websocket event: will_play" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1360" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="selected format OGG_VORBIS_320 (8e561abb815cd33530c903d5c3605c2ac6505614)" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:07 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=debug msg="requested aes key for file 8e561abb815cd33530c903d5c3605c2ac6505614, gid: 7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:08 volumio go-librespot[3068]: time="2025-09-01T21:23:07+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:08 volumio go-librespot[3068]: time="2025-09-01T21:23:08+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1124" Sep 01 21:23:08 volumio volumio[2811]: info: Initializing connection to go-librespot Websocket Sep 01 21:23:08 volumio go-librespot[3068]: time="2025-09-01T21:23:08+03:00" level=debug msg="new websocket client" Sep 01 21:23:08 volumio volumio[2811]: info: Connection to go-librespot Websocket established Sep 01 21:23:09 volumio mpd[3154]: Sep 01 21:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Sep 01 21:23:09 volumio systemd[1]: Started Music Player Daemon. Sep 01 21:23:09 volumio sudo[3026]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:09 volumio sudo[3124]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:09 volumio sudo[3034]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:09 volumio sudo[3150]: pam_unix(sudo:session): session closed for user root Sep 01 21:23:09 volumio volumio[2811]: error: MPD error: The expression evaluated to a falsy value: Sep 01 21:23:09 volumio volumio[2811]: assert.ok(self.idling) Sep 01 21:23:09 volumio volumio[2811]: error: The expression evaluated to a falsy value: Sep 01 21:23:09 volumio volumio[2811]: assert.ok(self.idling) Sep 01 21:23:09 volumio volumio[2811]: error: MPD error: The expression evaluated to a falsy value: Sep 01 21:23:09 volumio volumio[2811]: assert.ok(self.idling) Sep 01 21:23:09 volumio volumio[2811]: error: The expression evaluated to a falsy value: Sep 01 21:23:09 volumio volumio[2811]: assert.ok(self.idling) Sep 01 21:23:09 volumio volumio[2811]: error: MPD error: The expression evaluated to a falsy value: Sep 01 21:23:09 volumio volumio[2811]: assert.ok(self.idling) Sep 01 21:23:09 volumio volumio[2811]: error: The expression evaluated to a falsy value: Sep 01 21:23:09 volumio volumio[2811]: assert.ok(self.idling) Sep 01 21:23:09 volumio volumio[2811]: info: MPD running with PID3154 Sep 01 21:23:09 volumio volumio[2811]: ,establishing connection Sep 01 21:23:09 volumio volumio[2811]: error: updateQueue error: null Sep 01 21:23:09 volumio volumio[2811]: info: Completed starting Core Plugins Sep 01 21:23:09 volumio volumio[2811]: info: ------------------------------------------- Sep 01 21:23:09 volumio volumio[2811]: info: ----- MyVolumio plugins startup ---- Sep 01 21:23:09 volumio volumio[2811]: info: ------------------------------------------- Sep 01 21:23:09 volumio volumio[2811]: info: [MyVolumio PluginManager] Fetching plans data.... Sep 01 21:23:09 volumio go-librespot[3068]: time="2025-09-01T21:23:09+03:00" level=debug msg="fetched first chunk of 18, total size is 8914732 bytes" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:09 volumio volumio[2811]: error: updateQueue error: null Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=trace msg="seek to 23001ms (diff: 166ms, samples: 1014344, bytes: 810030)" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="created new output device" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=info msg="loaded track \"תתן אחרית לעמך\" (paused: false, position: 23001ms, duration: 210000ms, prefetched: false)" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:11 volumio volumio[2811]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Sep 01 21:23:11 volumio volumio[2811]: info: FusionDsp - ---- read samplerate from file: 44100 Sep 01 21:23:11 volumio volumio[2811]: info: camilladsp stopping service pid 3101... Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="fetched chunk 4/17, size: 524288" uri="spotify:track:7ozVH6xgcWCD66VhFhLXOh" Sep 01 21:23:11 volumio volumio[2811]: info: camilladsp service terminated, instance 1 Sep 01 21:23:11 volumio volumio[2811]: info: FusionDsp - If filter freq >samplerate/2 then disable it Sep 01 21:23:11 volumio volumio[2811]: info: camilladsp service started and running in background, instance 1 Sep 01 21:23:11 volumio volumio[2811]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Sep 01 21:23:11 volumio volumio[2811]: info: FusionDsp - ---- read samplerate from file: 44100 Sep 01 21:23:11 volumio volumio[2811]: info: FusionDsp - If filter freq >samplerate/2 then disable it Sep 01 21:23:11 volumio volumio[2811]: error: FusionDsp - WebSocket error: [object Object] Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=trace msg="scheduling prefetch in 157s" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=trace msg="emitting websocket event: metadata" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=trace msg="emitting websocket event: active" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="sending successful reply for dealer request" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 01 21:23:11 volumio volumio[2811]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:7ozVH6xgcWCD66VhFhLXOh","name":"תתן אחרית לעמך","artist_names":["Moti Weiss"],"album_name":"הנה זה בא","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f9a8f238d5f59dfc03497064","position":23001,"duration":210000,"release_date":"year:2024 month:12 day:6","track_number":3,"disc_number":1}} Sep 01 21:23:11 volumio volumio[2811]: SPOTIFY: received: {"type":"active","data":null} Sep 01 21:23:11 volumio volumio[2811]: info: Aligning Spotify Volume to Volumio Volume Sep 01 21:23:11 volumio volumio[2811]: info: CoreCommandRouter::volumioGetState Sep 01 21:23:11 volumio volumio[2811]: info: CorePlayQueue::getTrack 0 Sep 01 21:23:11 volumio volumio[2811]: info: Getting Spotify volume Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 01 21:23:11 volumio go-librespot[3068]: time="2025-09-01T21:23:11+03:00" level=trace msg="emitting websocket event: playing" Sep 01 21:23:11 volumio volumio[2811]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Sep 01 21:23:11 volumio volumio[2811]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:7ozVH6xgcWCD66VhFhLXOh","resume":false,"play_origin":"com.spotify.gaia"}} Sep 01 21:23:11 volumio volumio[2811]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 21:23:11 volumio volumio[2811]: TypeError: Cannot read property 'service' of undefined Sep 01 21:23:11 volumio volumio[2811]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Sep 01 21:23:11 volumio volumio[2811]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Sep 01 21:23:11 volumio volumio[2811]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Sep 01 21:23:11 volumio volumio[2811]: at WebSocket.emit (events.js:315:20) Sep 01 21:23:11 volumio volumio[2811]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Sep 01 21:23:11 volumio volumio[2811]: at Receiver.emit (events.js:315:20) Sep 01 21:23:11 volumio volumio[2811]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Sep 01 21:23:11 volumio volumio[2811]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Sep 01 21:23:11 volumio volumio[2811]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Sep 01 21:23:11 volumio volumio[2811]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Sep 01 21:23:11 volumio volumio[2811]: at writeOrBuffer (internal/streams/writable.js:358:12) Sep 01 21:23:11 volumio volumio[2811]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Sep 01 21:23:11 volumio volumio[2811]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Sep 01 21:23:11 volumio volumio[2811]: at Socket.emit (events.js:315:20) Sep 01 21:23:11 volumio volumio[2811]: at addChunk (internal/streams/readable.js:309:12) Sep 01 21:23:11 volumio volumio[2811]: at readableAddChunk (internal/streams/readable.js:284:9) Sep 01 21:23:11 volumio volumio[2811]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 01 21:23:12 volumio sudo[3196]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-09-01 21:22 Sep 01 21:23:12 volumio sudo[3196]: 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="29866754e5f1d7e4d0f581c10d9f22852f6f21db" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="fc4c820ddd3b5fc1a7a6b54ef112273ebd122010" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 26 Jul 2025 10:25:36 AM CEST" VOLUMIO_VERSION="3.832" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="cf6e14681b2ecbbdc9a62186b0f3114c"