-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Thu 2024-10-17 11:02:58 CEST. -- Oct 17 11:01:26 volumio2 ntpd[772]: 162.159.200.1 local addr 192.168.178.38 -> Oct 17 11:01:39 volumio2 volumio[977]: info: Oct 17 11:01:39 volumio2 volumio[977]: ---------------------------- MPD announces system playlist update Oct 17 11:01:39 volumio2 volumio[977]: info: Ignoring MPD Status Update Oct 17 11:01:39 volumio2 volumio[977]: info: Oct 17 11:01:39 volumio2 volumio[977]: ---------------------------- MPD announces state update: player Oct 17 11:01:39 volumio2 volumio[977]: info: ControllerMpd::getState Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::sendMpdCommand status Oct 17 11:01:39 volumio2 volumio[977]: info: Oct 17 11:01:39 volumio2 volumio[977]: ---------------------------- MPD announces system playlist update Oct 17 11:01:39 volumio2 volumio[977]: info: Ignoring MPD Status Update Oct 17 11:01:39 volumio2 volumio[977]: info: Oct 17 11:01:39 volumio2 volumio[977]: ---------------------------- MPD announces state update: player Oct 17 11:01:39 volumio2 volumio[977]: info: ControllerMpd::getState Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::sendMpdCommand status Oct 17 11:01:39 volumio2 volumio[977]: info: ------------------------------ 8ms Oct 17 11:01:39 volumio2 volumio[977]: info: sendMpdCommand status took 5 milliseconds Oct 17 11:01:39 volumio2 volumio[977]: info: ------------------------------ 5ms Oct 17 11:01:39 volumio2 volumio[977]: info: sendMpdCommand status took 3 milliseconds Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::parseState Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::parseState Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 17 11:01:39 volumio2 volumio[977]: info: Oct 17 11:01:39 volumio2 volumio[977]: ---------------------------- MPD announces system playlist update Oct 17 11:01:39 volumio2 volumio[977]: info: Ignoring MPD Status Update Oct 17 11:01:39 volumio2 volumio[977]: info: Oct 17 11:01:39 volumio2 volumio[977]: ---------------------------- MPD announces state update: player Oct 17 11:01:39 volumio2 volumio[977]: info: ControllerMpd::getState Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::sendMpdCommand status Oct 17 11:01:39 volumio2 volumio[977]: info: sendMpdCommand playlistinfo took 6 milliseconds Oct 17 11:01:39 volumio2 volumio[977]: info: sendMpdCommand playlistinfo took 6 milliseconds Oct 17 11:01:39 volumio2 volumio[977]: info: ------------------------------ 4ms Oct 17 11:01:39 volumio2 volumio[977]: info: sendMpdCommand status took 4 milliseconds Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::parseTrackInfo Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::parseTrackInfo Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::parseState Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 17 11:01:39 volumio2 volumio[977]: info: ControllerMpd::pushState Oct 17 11:01:39 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:01:39 volumio2 volumio[977]: info: CorePlayQueue::getTrack 0 Oct 17 11:01:39 volumio2 volumio[977]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Oct 17 11:01:39 volumio2 volumio[977]: info: ControllerMpd::pushState Oct 17 11:01:39 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:01:39 volumio2 volumio[977]: info: CorePlayQueue::getTrack 0 Oct 17 11:01:39 volumio2 volumio[977]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Oct 17 11:01:39 volumio2 volumio[977]: info: ------------------------------ 21ms Oct 17 11:01:39 volumio2 volumio[977]: info: ------------------------------ 17ms Oct 17 11:01:39 volumio2 volumio[977]: info: sendMpdCommand playlistinfo took 5 milliseconds Oct 17 11:01:39 volumio2 volumio[977]: verbose: ControllerMpd::parseTrackInfo Oct 17 11:01:39 volumio2 volumio[977]: info: ControllerMpd::pushState Oct 17 11:01:39 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:01:39 volumio2 volumio[977]: info: CorePlayQueue::getTrack 0 Oct 17 11:01:39 volumio2 volumio[977]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Oct 17 11:01:39 volumio2 volumio[977]: info: ------------------------------ 17ms Oct 17 11:01:43 volumio2 ntpd[772]: 85.10.240.253 local addr 192.168.178.38 -> Oct 17 11:02:10 volumio2 sudo[3046]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 17 11:02:10 volumio2 sudo[3046]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 11:02:10 volumio2 sudo[3046]: pam_unix(sudo:session): session closed for user root Oct 17 11:02:10 volumio2 sudo[3048]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 17 11:02:10 volumio2 sudo[3048]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 17 11:02:10 volumio2 sudo[3048]: pam_unix(sudo:session): session closed for user root Oct 17 11:02:10 volumio2 volumio[977]: verbose: New Socket.io Connection to 192.168.178.38 from 192.168.178.20 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) SamsungBrowser/26.0 Chrome/122.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Oct 17 11:02:10 volumio2 volumio[977]: info: CoreCommandRouter::volumioGetState Oct 17 11:02:10 volumio2 volumio[977]: info: CorePlayQueue::getTrack 0 Oct 17 11:02:10 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 17 11:02:10 volumio2 volumio[977]: info: Listing playlists Oct 17 11:02:10 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 17 11:02:10 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Oct 17 11:02:10 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Oct 17 11:02:10 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 17 11:02:16 volumio2 volumio[977]: info: CoreCommandRouter::volumioGetVisibleSources Oct 17 11:02:16 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 17 11:02:16 volumio2 volumio[977]: info: CoreCommandRouter::volumioGetQueue Oct 17 11:02:16 volumio2 volumio[977]: info: CoreStateMachine::getQueue Oct 17 11:02:16 volumio2 volumio[977]: info: CorePlayQueue::getQueue Oct 17 11:02:23 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: ytmusic , handleBrowseUri Oct 17 11:02:23 volumio2 volumio[977]: info: [ytmusic-browse] browseUri: ytmusic Oct 17 11:02:23 volumio2 volumio[977]: info: Preload queue cleared Oct 17 11:02:28 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 17 11:02:28 volumio2 volumio[977]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 17 11:02:28 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 17 11:02:28 volumio2 volumio[977]: info: Received Get System Version Oct 17 11:02:28 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 17 11:02:28 volumio2 volumio[977]: info: Received Get System Info Oct 17 11:02:28 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 17 11:02:28 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 17 11:02:28 volumio2 volumio[977]: info: Discovery: Getting this device information Oct 17 11:02:28 volumio2 volumio[977]: info: CoreCommandRouter::volumioGetState Oct 17 11:02:28 volumio2 volumio[977]: info: CorePlayQueue::getTrack 0 Oct 17 11:02:28 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 17 11:02:29 volumio2 volumio[977]: Searching all installed plugins Oct 17 11:02:29 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 17 11:02:29 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: , search Oct 17 11:02:29 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: webradio , search Oct 17 11:02:29 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Oct 17 11:02:29 volumio2 volumio[977]: info: [ytmusic] InnertubeLoader: creating Innertube instance... Oct 17 11:02:29 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: 80s80s , search Oct 17 11:02:37 volumio2 volumio[977]: info: [ytmusic] InnertubeLoader: creating Auth instance... Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 17 11:02:37 volumio2 volumio[977]: info: Fehler bei der Kommunikation mit SHOUTCAST Oct 17 11:02:37 volumio2 volumio[977]: error: Search in plugin webradio timed out Oct 17 11:02:37 volumio2 volumio[977]: error: Search in plugin ytmusic timed out Oct 17 11:02:37 volumio2 volumio[977]: info: All search sources collected, pushing search results Oct 17 11:02:37 volumio2 volumio[977]: Searching all installed plugins Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: webradio , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: 80s80s , search Oct 17 11:02:37 volumio2 volumio[977]: Searching all installed plugins Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: webradio , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: 80s80s , search Oct 17 11:02:37 volumio2 volumio[977]: Searching all installed plugins Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: webradio , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Oct 17 11:02:37 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: 80s80s , search Oct 17 11:02:37 volumio2 volumio[977]: error: Failed search in plugin webradio: Error: Unable to resolve or reject the same promise twice Oct 17 11:02:37 volumio2 volumio[977]: Upnp client error: Error: This socket has been ended by the other party Oct 17 11:02:37 volumio2 volumio[977]: Upnp client error: Error: This socket has been ended by the other party Oct 17 11:02:38 volumio2 volumio[977]: info: All search sources collected, pushing search results Oct 17 11:02:38 volumio2 volumio[977]: info: All search sources collected, pushing search results Oct 17 11:02:38 volumio2 volumio[977]: info: All search sources collected, pushing search results Oct 17 11:02:38 volumio2 volumio[977]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 17 11:02:38 volumio2 volumio[977]: info: [ytmusic] InnertubeLoader: Auth instance created (status: pending sign-in) Oct 17 11:02:38 volumio2 volumio[977]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 17 11:02:38 volumio2 volumio[977]: info: CoreCommandRouter::volumioGetState Oct 17 11:02:38 volumio2 volumio[977]: info: CorePlayQueue::getTrack 0 Oct 17 11:02:38 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:39 volumio2 volumio[977]: error: Failed search in plugin ytmusic: Error: Unable to resolve or reject the same promise twice Oct 17 11:02:50 volumio2 go-librespot[1149]: time="2024-10-17T11:02:50+02:00" level=debug msg="obtained new client token: AADvQcbPsb3GfqArRpJ3+VRW27lwEc70TK/Y6Y67VeH0kUFgxswSQYWSJO/qGi6eUcS4fU0/JeS4T2LLlVARv2r3MCuStm4vNzLNwMUy1RG/X2oJ+l86aOS7BpCY7Aoagms/ekmVKllN941nOjOohVRj3BqZZQoKNGmD/JnL6F0j2mtM76vdpt1hLKHqIz8EBIGwq2Gnp618H33Ii+nOTaD0IOGbWaZasRXqXo1KvmIvVP20qwh74KHrSovipA==" Oct 17 11:02:50 volumio2 go-librespot[1149]: time="2024-10-17T11:02:50+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Oct 17 11:02:50 volumio2 go-librespot[1149]: time="2024-10-17T11:02:50+02:00" level=info msg="connected to ap-gew4.spotify.com:443" Oct 17 11:02:50 volumio2 go-librespot[1149]: time="2024-10-17T11:02:50+02:00" level=debug msg="completed keyexchange" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="completed challenge" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="authenticated as pvieth" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="authenticated as pvieth" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="dealer connection opened" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=info msg="accepted zeroconf user pvieth from S20 von Peter" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="autoplay enabled: false" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="received connection id: ODJjMTVmZDgtOGIwNy00ZDkzLWJhMmEtMzM0MDAzYjc3MWZhK2RlYWxlcit0Y3A6Ly8wYWNhNThiMi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRUZEODQxMjRDOTg2NEI5OTNDQkI2MzlERjVGRTYwRTM0RUJCOTlFNTY2NjVBMzExRjM0RjZDNjI0OEMyNUZGRA==" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="handling transfer player command from 0524e26feb140dc86adfa34fa3fa0b9926685ff6" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:3FmcU2xa8VTERumKcSuyBq" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=trace msg="fetched new page 0 with 35 items (list: 35)" uri="spotify:playlist:3FmcU2xa8VTERumKcSuyBq" Oct 17 11:02:51 volumio2 go-librespot[1149]: time="2024-10-17T11:02:51+02:00" level=debug msg="loading track (paused: true, position: 31393ms)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=trace msg="emitting websocket event: will_play" Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","play_origin":"playlist"}} Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="selected format OGG_VORBIS_320 (0133f15b1602585c5d602a3d231ac8366b0e95cd)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="requested aes key for file 0133f15b1602585c5d602a3d231ac8366b0e95cd, gid: 0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1345" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="fetched first chunk of 14, total size is 7091648 bytes" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1127" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=trace msg="seek to 31393ms (diff: 197ms, samples: 1384431, bytes: 1447460)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="created new output device" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=info msg="loaded track \"Heartwaves (feat. Sam Gray)\" (paused: true, position: 31393ms, duration: 158737ms, prefetched: false)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=trace msg="emitting websocket event: metadata" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=trace msg="emitting websocket event: active" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="sending successful reply for dealer request" Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","name":"Heartwaves (feat. Sam Gray)","artist_names":["Klingande","Solar State","Sam Gray"],"album_name":"Heartwaves (feat. Sam Gray)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","position":31393,"duration":158737,"release_date":"year:2023 month:5 day:5","track_number":1,"disc_number":1}} Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: received: {"type":"active","data":null} Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 17 11:02:52 volumio2 volumio[977]: info: Aligning Spotify Volume to Volumio Volume Oct 17 11:02:52 volumio2 volumio[977]: info: CoreCommandRouter::volumioGetState Oct 17 11:02:52 volumio2 volumio[977]: info: CorePlayQueue::getTrack 0 Oct 17 11:02:52 volumio2 volumio[977]: info: Setting Spotify Volume from Volumio: 85 Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=trace msg="emitting websocket event: paused" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="handling resume player command from 0524e26feb140dc86adfa34fa3fa0b9926685ff6" Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","play_origin":"playlist"}} Oct 17 11:02:52 volumio2 volumio[977]: info: Spotify is playing in volatile mode Oct 17 11:02:52 volumio2 volumio[977]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: UNSET VOLATILE Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: {"status":"play","position":0,"title":"Echo & The Bunnymen - The Killing Moon","artist":"80s80s Wave","album":"","albumart":"https://is1-ssl.mzstatic.com/image/thumb/Features125/v4/c4/ef/68/c4ef6820-80f3-5fed-a400-16db4c6f6a8b/dj.lmwkvacf.jpg/600x600bb.jpg","uri":"http://streams.80s80s.de/wave/mp3-192/volumio","trackType":"80s80s Radio","seek":309463,"duration":"329","samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":true,"repeatSingle":false,"consume":false,"volume":85,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} Oct 17 11:02:52 volumio2 volumio[977]: info: Setting Spotify stop after unset volatile call Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: {"status":"pause","service":"spop","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 17 11:02:52 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:02:52 volumio2 volumio[977]: info: CoreStateMachine::pushState Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=trace msg="seek to 31393ms (diff: 197ms, samples: 1384431, bytes: 1447460)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:52 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 11:02:52 volumio2 volumio[977]: info: CoreCommandRouter::volumioPushState Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="resume track at 31196ms" Oct 17 11:02:52 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=trace msg="scheduling prefetch in 98s" Oct 17 11:02:52 volumio2 go-librespot[1149]: time="2024-10-17T11:02:52+02:00" level=debug msg="sending successful reply for dealer request" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="emitting websocket event: playing" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="handling resume player command from 0524e26feb140dc86adfa34fa3fa0b9926685ff6" Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","play_origin":"playlist"}} Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: {"status":"play","service":"spop","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreStateMachine::pushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::volumioPushState Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="seek to 31313ms (diff: 184ms, samples: 1380903, bytes: 1443198)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="resume track at 31196ms" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="scheduling prefetch in 97s" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="sending successful reply for dealer request" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="emitting websocket event: playing" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="handling transfer player command from 0524e26feb140dc86adfa34fa3fa0b9926685ff6" Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","play_origin":"playlist"}} Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: {"status":"play","service":"spop","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:3FmcU2xa8VTERumKcSuyBq" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="fetched new page 0 with 35 items (list: 35)" uri="spotify:playlist:3FmcU2xa8VTERumKcSuyBq" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="loading track (paused: true, position: 31393ms)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 volumio[977]: info: CoreStateMachine::pushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::volumioPushState Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="emitting websocket event: will_play" Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","play_origin":"playlist"}} Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="selected format OGG_VORBIS_320 (0133f15b1602585c5d602a3d231ac8366b0e95cd)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="requested aes key for file 0133f15b1602585c5d602a3d231ac8366b0e95cd, gid: 0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: {"status":"play","service":"spop","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreStateMachine::pushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::volumioPushState Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="fetched first chunk of 14, total size is 7091648 bytes" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 volumio[977]: info: Spotify Stop Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: SPOTIFY STOP Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: {"status":"play","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","codec":"ogg","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":85,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: {"status":"play","service":"spop","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreStateMachine::pushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::volumioPushState Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="fetched chunk 5/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="seek to 31393ms (diff: 197ms, samples: 1384431, bytes: 1447460)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=info msg="loaded track \"Heartwaves (feat. Sam Gray)\" (paused: true, position: 31393ms, duration: 158737ms, prefetched: false)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="fetched chunk 4/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="emitting websocket event: metadata" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="emitting websocket event: active" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="sending successful reply for dealer request" Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","name":"Heartwaves (feat. Sam Gray)","artist_names":["Klingande","Solar State","Sam Gray"],"album_name":"Heartwaves (feat. Sam Gray)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","position":31393,"duration":158737,"release_date":"year:2023 month:5 day:5","track_number":1,"disc_number":1}} Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: received: {"type":"active","data":null} Oct 17 11:02:53 volumio2 volumio[977]: info: Aligning Spotify Volume to Volumio Volume Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::volumioGetState Oct 17 11:02:53 volumio2 volumio[977]: info: Setting Spotify Volume from Volumio: 85 Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:53 volumio2 go-librespot[1149]: time="2024-10-17T11:02:53+02:00" level=trace msg="emitting websocket event: paused" Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","play_origin":"playlist"}} Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: {"status":"pause","service":"spop","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreStateMachine::pushState Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 11:02:53 volumio2 volumio[977]: info: CoreCommandRouter::volumioPushState Oct 17 11:02:53 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:55 volumio2 volumio[977]: SPOTIFY: SETTING SPOTIFY VOLUME 85 Oct 17 11:02:55 volumio2 volumio[977]: info: Sending Spotify command with payload to local API: /player/volume Oct 17 11:02:55 volumio2 go-librespot[1149]: time="2024-10-17T11:02:55+02:00" level=debug msg="update volume to 55704/65535" Oct 17 11:02:55 volumio2 go-librespot[1149]: time="2024-10-17T11:02:55+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 17 11:02:55 volumio2 go-librespot[1149]: time="2024-10-17T11:02:55+02:00" level=trace msg="emitting websocket event: volume" Oct 17 11:02:55 volumio2 volumio[977]: SPOTIFY: received: {"type":"volume","data":{"value":85,"max":100}} Oct 17 11:02:55 volumio2 volumio[977]: SPOTIFY: RECEIVED SPOTIFY VOLUME 85 Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=debug msg="handling resume player command from 0524e26feb140dc86adfa34fa3fa0b9926685ff6" Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=trace msg="seek to 31393ms (diff: 197ms, samples: 1384431, bytes: 1447460)" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=debug msg="resume track at 31196ms" Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=trace msg="scheduling prefetch in 98s" Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=debug msg="sending successful reply for dealer request" Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 17 11:02:56 volumio2 go-librespot[1149]: time="2024-10-17T11:02:56+02:00" level=trace msg="emitting websocket event: playing" Oct 17 11:02:56 volumio2 volumio[977]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","play_origin":"playlist"}} Oct 17 11:02:56 volumio2 volumio[977]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 11:02:56 volumio2 volumio[977]: SPOTIFY: {"status":"play","service":"spop","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 17 11:02:56 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:02:56 volumio2 volumio[977]: info: CoreStateMachine::pushState Oct 17 11:02:56 volumio2 volumio[977]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 17 11:02:56 volumio2 volumio[977]: info: CoreCommandRouter::volumioPushState Oct 17 11:02:56 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:56 volumio2 volumio[977]: SPOTIFY: PUSH STATE SPOTIFY Oct 17 11:02:56 volumio2 volumio[977]: SPOTIFY: {"status":"play","service":"spop","title":"Heartwaves (feat. Sam Gray)","artist":"Klingande, Solar State, Sam Gray","album":"Heartwaves (feat. Sam Gray)","albumart":"https://i.scdn.co/image/ab67616d00001e024ea5ba6f66141f95b1be090f","uri":"spotify:track:0ucfUk4WEPz456gjrkv3uo","trackType":"spotify","seek":31393,"duration":158,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 17 11:02:56 volumio2 volumio[977]: info: CoreCommandRouter::servicePushState Oct 17 11:02:56 volumio2 volumio[977]: info: CoreStateMachine::pushState Oct 17 11:02:56 volumio2 volumio[977]: info: CoreCommandRouter::volumioPushState Oct 17 11:02:56 volumio2 volumio[977]: SPOTIFY: RECEIVED VOLUMIO VOLUME 85 Oct 17 11:02:57 volumio2 volumio[977]: info: [1729155777988] [80s80s] Pushing the next song state Echo & The Bunnymen - The Killing Moon and getting next track. Oct 17 11:02:57 volumio2 volumio[977]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 11:02:57 volumio2 volumio[977]: TypeError: Cannot set property 'name' of undefined Oct 17 11:02:57 volumio2 volumio[977]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Oct 17 11:02:57 volumio2 volumio[977]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Oct 17 11:02:57 volumio2 volumio[977]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Oct 17 11:02:57 volumio2 volumio[977]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Oct 17 11:02:57 volumio2 volumio[977]: at processImmediate (internal/timers.js:461:21) Oct 17 11:02:58 volumio2 volumio[977]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 17 11:02:58 volumio2 go-librespot[1149]: time="2024-10-17T11:02:58+02:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:0ucfUk4WEPz456gjrkv3uo" Oct 17 11:02:58 volumio2 sudo[3183]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-17 11:01 Oct 17 11:02:58 volumio2 sudo[3183]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"