-- Logs begin at Tue 2024-10-29 19:21:38 CET, end at Wed 2025-05-14 11:34:59 CEST. -- May 14 11:33:36 volumio systemd[1]: Starting Daily apt download activities... May 14 11:33:36 volumio systemd[1]: Starting Daily man-db regeneration... May 14 11:33:36 volumio systemd[1]: man-db.service: Succeeded. May 14 11:33:36 volumio systemd[1]: Started Daily man-db regeneration. May 14 11:33:37 volumio volumio[1010]: info: Initializing connection to go-librespot Websocket May 14 11:33:37 volumio volumio[1010]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 14 11:33:39 volumio go-librespot[1824]: time="2025-05-14T11:33:39+02:00" level=debug msg="obtained new client token: AACaarhngjbmE2Kobw58TdtZIQn7xLsDJlRWfAC7DrAaAkKJOEHrSxkN6UOmf19hnGB9bwj+6LBbJUNs1pHZ0anySbuBY99uBgFAHc10bk5KKgiq7FjTZ7tIKYv43mDoYexZJlHhhV7s/oiPsgvrn6YbWnqc1gAKbyHKtInNde9Z8NA/ESZLPqlyFwde27gNiMoD1A013r9nhbZTs0w5Nt6vZjuA+R8y+R4rplSVcJn5mYYJZS3hgQjgtEYykrk=" May 14 11:33:39 volumio go-librespot[1824]: time="2025-05-14T11:33:39+02:00" level=debug msg="stored credentials found for obd8a6bj9htvkzyyaqk92n91y" May 14 11:33:39 volumio go-librespot[1824]: time="2025-05-14T11:33:39+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 14 11:33:39 volumio systemd[1]: apt-daily.service: Succeeded. May 14 11:33:39 volumio systemd[1]: Started Daily apt download activities. May 14 11:33:39 volumio systemd[1]: Starting Daily apt upgrade and clean activities... May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.943131, 0] ../source3/libsmb/nmblib.c:917(send_udp) May 14 11:33:39 volumio nmbd[762]: Packet send failed to 169.254.255.255(138) ERRNO=Network is unreachable May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.943785, 0] ../source3/libsmb/nmblib.c:917(send_udp) May 14 11:33:39 volumio nmbd[762]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.944068, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) May 14 11:33:39 volumio nmbd[762]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.944280, 0] ../source3/libsmb/nmblib.c:917(send_udp) May 14 11:33:39 volumio nmbd[762]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.944438, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) May 14 11:33:39 volumio nmbd[762]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.944593, 0] ../source3/libsmb/nmblib.c:917(send_udp) May 14 11:33:39 volumio nmbd[762]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.944709, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) May 14 11:33:39 volumio nmbd[762]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.944866, 0] ../source3/libsmb/nmblib.c:917(send_udp) May 14 11:33:39 volumio nmbd[762]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.944978, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) May 14 11:33:39 volumio nmbd[762]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.945108, 0] ../source3/libsmb/nmblib.c:917(send_udp) May 14 11:33:39 volumio nmbd[762]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable May 14 11:33:39 volumio nmbd[762]: [2025/05/14 11:33:39.945209, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) May 14 11:33:39 volumio nmbd[762]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed May 14 11:33:40 volumio volumio[1010]: info: Initializing connection to go-librespot Websocket May 14 11:33:40 volumio go-librespot[1824]: time="2025-05-14T11:33:40+02:00" level=debug msg="new websocket client" May 14 11:33:40 volumio volumio[1010]: info: Connection to go-librespot Websocket established May 14 11:33:40 volumio volumio[1010]: info: Discovery: A device disappeared from network May 14 11:33:40 volumio volumio[1010]: info: Discovery: Device volumio disappeared from network May 14 11:33:40 volumio go-librespot[1824]: time="2025-05-14T11:33:40+02:00" level=debug msg="completed keyexchange" May 14 11:33:40 volumio volumio[1010]: info: Discovery: adding 0ef5abb0-bf0c-431b-9ab4-81d4ab6d8b81 May 14 11:33:40 volumio volumio[1010]: info: Discovery: Found device Volumio May 14 11:33:40 volumio volumio[1010]: info: CoreCommandRouter::volumioGetState May 14 11:33:40 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso May 14 11:33:40 volumio volumio[1010]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso May 14 11:33:40 volumio volumio[1010]: info: Adding plugin bluetooth to MyMusic Plugins May 14 11:33:40 volumio volumio[1010]: info: Adding plugin multiroom to MyMusic Plugins May 14 11:33:40 volumio volumio[1010]: info: Adding plugin metavolumio to MyMusic Plugins May 14 11:33:40 volumio volumio[1010]: info: Adding plugin cd_controller to MyMusic Plugins May 14 11:33:40 volumio volumio[1010]: info: Adding plugin smart_inputs to MyMusic Plugins May 14 11:33:41 volumio volumio[1010]: info: Adding plugin tidalconnect to MyMusic Plugins May 14 11:33:41 volumio volumio[1010]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... May 14 11:33:41 volumio go-librespot[1824]: time="2025-05-14T11:33:41+02:00" level=debug msg="completed challenge" May 14 11:33:41 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. May 14 11:33:41 volumio systemd[1]: Started Daily apt upgrade and clean activities. May 14 11:33:41 volumio go-librespot[1824]: time="2025-05-14T11:33:41+02:00" level=debug msg="authenticated as obd8a6bj9htvkzyyaqk92n91y" May 14 11:33:42 volumio go-librespot[1824]: time="2025-05-14T11:33:42+02:00" level=debug msg="authenticated as obd8a6bj9htvkzyyaqk92n91y" May 14 11:33:42 volumio go-librespot[1824]: time="2025-05-14T11:33:42+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 14 11:33:42 volumio volumio[1010]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded May 14 11:33:42 volumio volumio[1010]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio May 14 11:33:42 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:33:42 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:33:42 volumio volumio[1010]: info: Starting MyVolumio Remote Streaming Endpoints May 14 11:33:42 volumio volumio[1010]: info: MyVolumio login type: Token May 14 11:33:42 volumio volumio[1010]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started May 14 11:33:42 volumio volumio[1010]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... May 14 11:33:42 volumio go-librespot[1824]: time="2025-05-14T11:33:42+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 14 11:33:42 volumio ntpd[818]: receive: Unexpected origin timestamp 0xebcee1f4.ed5fdb72 does not match aorg 0xebcee1f6.ed40a256 from server@193.158.22.13 xmt 0xebcee1f6.eecf307b May 14 11:33:43 volumio ntpd[818]: receive: Unexpected origin timestamp 0xebcee1f4.ed5ac365 does not match aorg 0xebcee1f6.ed3d7de9 from server@157.230.98.101 xmt 0xebcee1f6.ed6922ba May 14 11:33:43 volumio ntpd[818]: receive: Unexpected origin timestamp 0xebcee1f4.ed4e0eeb does not match aorg 0xebcee1f6.ed3c0fff from server@185.197.135.21 xmt 0xebcee1f6.ece7a754 May 14 11:33:43 volumio ntpd[818]: receive: Unexpected origin timestamp 0xebcee1f4.ed797164 does not match aorg 0xebcee1f6.ed49ec6f from server@93.241.86.156 xmt 0xebcee1f6.ef27788c May 14 11:33:43 volumio ntpd[818]: receive: Unexpected origin timestamp 0xebcee1f4.ed64bb9d does not match aorg 0xebcee1f6.ed42d2b1 from server@94.130.184.193 xmt 0xebcee1f6.ef0e2fff May 14 11:33:43 volumio ntpd[818]: receive: Unexpected origin timestamp 0xebcee1f4.ed742d7b does not match aorg 0xebcee1f6.ed47f927 from server@78.46.162.102 xmt 0xebcee1f6.ef5cd670 May 14 11:33:43 volumio ntpd[818]: receive: Unexpected origin timestamp 0xebcee1f4.ed6ed59c does not match aorg 0xebcee1f6.ed441d3d from server@162.55.101.82 xmt 0xebcee1f6.f0e13b93 May 14 11:33:44 volumio volumio[1010]: info: Starting Streaming Service Transparent Proxy May 14 11:33:44 volumio volumio[1010]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded May 14 11:33:44 volumio volumio[1010]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services May 14 11:33:44 volumio volumio[1010]: info: Streaming services startup May 14 11:33:44 volumio volumio[1010]: info: Starting Streaming Daemon May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="dealer connection opened" May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="received connection id: MjcyZjE5NmUtMzBmMy00YzBiLTgxNmUtZTZhMzczNTdlOTBhK2RlYWxlcit0Y3A6Ly8wYWNhNThkYy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRkRBMTZFMTI1NEU3Nzg2QUVFMUI4MEM1QkEwQzRDM0QwRDBBQTNEMzAxNzU4NzdGNDlFQUJEQkM5RDY1QTVDMg==" May 14 11:33:44 volumio volumio[1010]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started May 14 11:33:44 volumio sudo[1960]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 14 11:33:44 volumio sudo[1960]: pam_unix(sudo:session): session opened for user root by (uid=0) May 14 11:33:44 volumio sudo[1960]: pam_unix(sudo:session): session closed for user root May 14 11:33:44 volumio volumio[1010]: info: Getting Spotify volume May 14 11:33:44 volumio volumio[1010]: error: error May 14 11:33:44 volumio volumio[1010]: error: Cannot start Volumio Streaming Daemon May 14 11:33:44 volumio volumio[1010]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 14 11:33:44 volumio volumio[1010]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 14 11:33:44 volumio volumio[1010]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 May 14 11:33:44 volumio volumio[1010]: info: CoreCommandRouter::volumioGetState May 14 11:33:44 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:33:44 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:33:44 volumio volumio[1010]: SPOTIFY: SPOTIFY VOLUME undefined May 14 11:33:44 volumio volumio[1010]: SPOTIFY: VOLUMIO VOLUME 78 May 14 11:33:44 volumio volumio[1010]: info: Aligning Spotify Volume to Volumio Volume May 14 11:33:44 volumio volumio[1010]: info: CoreCommandRouter::volumioGetState May 14 11:33:44 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:33:44 volumio volumio[1010]: info: Setting Spotify Volume from Volumio: 78 May 14 11:33:44 volumio volumio[1010]: SPOTIFY: SETTING SPOTIFY VOLUME 78 May 14 11:33:44 volumio volumio[1010]: info: Sending Spotify command with payload to local API: /player/volume May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="put connect state because NEW_DEVICE" May 14 11:33:44 volumio go-librespot[1824]: time="2025-05-14T11:33:44+02:00" level=debug msg="update volume to 51117/65535" May 14 11:33:44 volumio volumio[1010]: info: Spotify volume: 100 May 14 11:33:45 volumio go-librespot[1824]: time="2025-05-14T11:33:45+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 14 11:33:45 volumio go-librespot[1824]: time="2025-05-14T11:33:45+02:00" level=trace msg="emitting websocket event: volume" May 14 11:33:45 volumio volumio[1010]: SPOTIFY: received: {"type":"volume","data":{"value":77,"max":100}} May 14 11:33:45 volumio volumio[1010]: SPOTIFY: RECEIVED SPOTIFY VOLUME 78 May 14 11:33:45 volumio volumio[1010]: error: MyVolumio Custom Token format not valid, refreshing it May 14 11:33:45 volumio volumio[1010]: STREAMING PROXY: Starting server on port 3245 May 14 11:33:45 volumio volumio[1010]: Node JS runtime: 14 May 14 11:33:47 volumio volumio[1010]: info: MyVolumio login type: Token May 14 11:33:47 volumio volumio[1010]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN May 14 11:33:48 volumio volumio[1010]: info: MyVolumio token set successfully May 14 11:33:48 volumio volumio[1010]: info: MYVOLUMIO: Adding device May 14 11:33:48 volumio volumio[1010]: info: MYVOLUMIO: Evaluating Server May 14 11:33:49 volumio volumio[1010]: info: MyVolumio status changed May 14 11:33:49 volumio volumio[1010]: info: Streaming services startup May 14 11:33:49 volumio volumio[1010]: info: Starting Streaming Daemon May 14 11:33:49 volumio volumio[1010]: info: Removing browser output: myVolumio user plan is not superstar May 14 11:33:49 volumio volumio[1010]: info: Removing audio output: May 14 11:33:49 volumio volumio[1010]: info: Stoppping Tunnel 1 May 14 11:33:49 volumio sudo[1985]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service May 14 11:33:49 volumio sudo[1987]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service May 14 11:33:49 volumio sudo[1985]: pam_unix(sudo:session): session opened for user root by (uid=0) May 14 11:33:49 volumio sudo[1987]: pam_unix(sudo:session): session opened for user root by (uid=0) May 14 11:33:49 volumio sudo[1985]: pam_unix(sudo:session): session closed for user root May 14 11:33:49 volumio volumio[1010]: error: Cannot start Volumio Streaming Daemon May 14 11:33:49 volumio volumio[1010]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service May 14 11:33:49 volumio volumio[1010]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. May 14 11:33:49 volumio sudo[1987]: pam_unix(sudo:session): session closed for user root May 14 11:33:49 volumio volumio[1010]: info: Remote SSH Stopped May 14 11:33:50 volumio ntpd[818]: receive: Unexpected origin timestamp 0xebcee1fc.ed398793 does not match aorg 0xebcee1fe.ed3530f7 from server@217.79.189.239 xmt 0xebcee1fe.f4033a26 May 14 11:33:54 volumio volumio[1010]: info: Setting Geolocation for MyVolumio to eu2 May 14 11:33:54 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:33:54 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:33:54 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:33:55 volumio volumio[1010]: info: Updating MyVolumio device info May 14 11:33:55 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:33:55 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:33:55 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:33:56 volumio volumio[1010]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} May 14 11:33:56 volumio volumio[1010]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} May 14 11:33:57 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 14 11:33:57 volumio volumio[1010]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 May 14 11:33:57 volumio volumio[1010]: info: CoreCommandRouter::volumioGetState May 14 11:33:57 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:00 volumio volumio[1010]: info: MYVOLUMIO: Adding device May 14 11:34:00 volumio volumio[1010]: info: MYVOLUMIO: Evaluating Server May 14 11:34:02 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 14 11:34:02 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 14 11:34:02 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 14 11:34:02 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 14 11:34:02 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 14 11:34:02 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 14 11:34:02 volumio volumio[1010]: info: CoreCommandRouter::volumioGetBrowseSources May 14 11:34:02 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 14 11:34:10 volumio volumio[1010]: info: Airplay started streaming, receiving metadatas May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioStop May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::stop May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined May 14 11:34:10 volumio volumio[1010]: info: Airplay started streaming, receiving metadatas May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioStop May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::stop May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined May 14 11:34:10 volumio volumio[1010]: info: Airplay started streaming, receiving metadatas May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioStop May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::stop May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined May 14 11:34:10 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 May 14 11:34:10 volumio shairport-sync[1271]: % Total % Received % Xferd Average Speed Time Time Time Current May 14 11:34:10 volumio shairport-sync[1271]: Dload Upload Total Spent Left Speed May 14 11:34:10 volumio volumio[1010]: info: May 14 11:34:10 volumio volumio[1010]: ---------------------------- Client requests Start Airplay PlaybackRoutine May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startAirplayPlayback May 14 11:34:10 volumio volumio[1010]: info: Airplay playback start May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioStop May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::stop May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::setConsumeUpdateService undefined May 14 11:34:10 volumio shairport-sync[1271]: [158B blob data] May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: verbose: STATE SERVICE {"status":"play","service":"airplay_emulation","title":"I Bet You Look Good on the Dancefloor","artist":"Arctic Monkeys","album":"Whatever People Say I Am, That's What I'm Not","albumart":"/albumart?cacheid=69&web=Arctic%20Monkeys/Whatever%20People%20Say%20I%20Am%2C%20That's%20What%20I'm%20Not/extralarge&path=&metadata=false","uri":"","trackType":"airplay","seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"disableUiControls":true} May 14 11:34:10 volumio volumio[1010]: verbose: CURRENT POSITION 0 May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::syncState stateService play May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::syncState currentStatus stop May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: verbose: STATE SERVICE {"status":"play","service":"airplay_emulation","title":"I Bet You Look Good on the Dancefloor","artist":"Arctic Monkeys","album":"Whatever People Say I Am, That's What I'm Not","albumart":"/albumart?cacheid=69&web=Arctic%20Monkeys/Whatever%20People%20Say%20I%20Am%2C%20That's%20What%20I'm%20Not/extralarge&path=&metadata=false","uri":"","trackType":"airplay","seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"disableUiControls":true} May 14 11:34:10 volumio volumio[1010]: verbose: CURRENT POSITION 0 May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::syncState stateService play May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::syncState currentStatus play May 14 11:34:10 volumio volumio[1010]: info: Received an update from plugin. extracting info from payload May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: verbose: STATE SERVICE {"status":"play","service":"airplay_emulation","title":"I Bet You Look Good on the Dancefloor","artist":"Arctic Monkeys","album":"Whatever People Say I Am, That's What I'm Not","albumart":"/albumart?cacheid=69&web=Arctic%20Monkeys/Whatever%20People%20Say%20I%20Am%2C%20That's%20What%20I'm%20Not/extralarge&path=&metadata=false","uri":"","trackType":"airplay","seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"disableUiControls":true} May 14 11:34:10 volumio volumio[1010]: verbose: CURRENT POSITION 0 May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::syncState stateService play May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::syncState currentStatus play May 14 11:34:10 volumio volumio[1010]: info: Received an update from plugin. extracting info from payload May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioGetQueue May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::getQueue May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getQueue May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioGetQueue May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::getQueue May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getQueue May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioGetQueue May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::getQueue May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getQueue May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioGetQueue May 14 11:34:10 volumio volumio[1010]: info: CoreStateMachine::getQueue May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getQueue May 14 11:34:10 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:10 volumio volumio[1010]: SPOTIFY: SPOTIFY VOLUME 100 May 14 11:34:10 volumio volumio[1010]: SPOTIFY: VOLUMIO VOLUME 78 May 14 11:34:10 volumio volumio[1010]: SPOTIFY: DELTA VOLUME ENOUGH: true May 14 11:34:10 volumio volumio[1010]: info: Setting Spotify Volume from Volumio: 78 May 14 11:34:10 volumio volumio[1010]: SPOTIFY: SETTING SPOTIFY VOLUME 78 May 14 11:34:10 volumio volumio[1010]: info: Sending Spotify command with payload to local API: /player/volume May 14 11:34:10 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:10 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:10 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:10 volumio go-librespot[1824]: time="2025-05-14T11:34:10+02:00" level=debug msg="update volume to 51117/65535" May 14 11:34:10 volumio volumio[1010]: info: touch_display: Setting screensaver timeout to 0 seconds. May 14 11:34:10 volumio volumio[1010]: info: CoreCommandRouter::volumioGetState May 14 11:34:10 volumio volumio[1010]: info: CorePlayQueue::getTrack 0 May 14 11:34:11 volumio volumio[1010]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 May 14 11:34:11 volumio volumio[1010]: info: touch_display: Setting screensaver timeout to 0 seconds. May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:11 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:11 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:11 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:11 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:11 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:11 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:11 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:11 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:11 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:12 volumio go-librespot[1824]: time="2025-05-14T11:34:12+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 14 11:34:12 volumio go-librespot[1824]: time="2025-05-14T11:34:12+02:00" level=trace msg="emitting websocket event: volume" May 14 11:34:12 volumio volumio[1010]: SPOTIFY: received: {"type":"volume","data":{"value":77,"max":100}} May 14 11:34:12 volumio volumio[1010]: SPOTIFY: RECEIVED SPOTIFY VOLUME 78 May 14 11:34:13 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:13 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:13 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 14 11:34:13 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:13 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:13 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:13 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:13 volumio volumio[1010]: info: CoreCommandRouter::servicePushState May 14 11:34:13 volumio volumio[1010]: info: CoreStateMachine::pushState May 14 11:34:13 volumio volumio[1010]: info: CoreCommandRouter::volumioPushState May 14 11:34:13 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:13 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:13 volumio volumio[1010]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 May 14 11:34:26 volumio volumio[1010]: info: Setting Geolocation for MyVolumio to eu7 May 14 11:34:26 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:34:26 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:34:27 volumio volumio[1010]: info: Updating MyVolumio device info May 14 11:34:27 volumio volumio[1010]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 14 11:34:48 volumio volumio[1010]: error: Failed to add MyVolumio device: undefined May 14 11:34:50 volumio shairport-sync[1271]: {"time":1747215250440,"response":"startAirplayPlayback Success"}no RTSP header received May 14 11:34:56 volumio volumio[1010]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} May 14 11:34:59 volumio volumio[1010]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 14 11:34:59 volumio volumio[1010]: Error: read ECONNRESET May 14 11:34:59 volumio volumio[1010]: at TLSWrap.onStreamRead (internal/stream_base_commons.js:209:20) { May 14 11:34:59 volumio volumio[1010]: errno: -104, May 14 11:34:59 volumio volumio[1010]: code: 'ECONNRESET', May 14 11:34:59 volumio volumio[1010]: syscall: 'read' May 14 11:34:59 volumio volumio[1010]: } May 14 11:34:59 volumio volumio[1010]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 14 11:34:59 volumio sudo[2100]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-14 11:33 May 14 11:34:59 volumio sudo[2100]: 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"