-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Tue 2025-06-10 13:48:52 CEST. -- Jun 10 13:47:00 volumio volumio[1095]: info: go-librespot daemon successfully initialized Jun 10 13:47:01 volumio volumio[1095]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 10 13:47:03 volumio volumio[1095]: info: Initializing connection to go-librespot Websocket Jun 10 13:47:03 volumio go-librespot[1363]: time="2025-06-10T13:47:03+02:00" level=debug msg="new websocket client" Jun 10 13:47:03 volumio volumio[1095]: info: Connection to go-librespot Websocket established Jun 10 13:47:03 volumio volumio-remote-updater[721]: [2025-06-10 13:47:03] [connect] Successful connection Jun 10 13:47:03 volumio volumio[1095]: 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: 4 Jun 10 13:47:03 volumio volumio-remote-updater[721]: [2025-06-10 13:47:03] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1749556023 101 Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 10 13:47:05 volumio volumio[1095]: info: Adding plugin bluetooth to MyMusic Plugins Jun 10 13:47:05 volumio volumio[1095]: info: Adding plugin multiroom to MyMusic Plugins Jun 10 13:47:05 volumio volumio[1095]: info: Adding plugin metavolumio to MyMusic Plugins Jun 10 13:47:05 volumio volumio[1095]: info: Adding plugin cd_controller to MyMusic Plugins Jun 10 13:47:05 volumio volumio[1095]: info: Adding plugin qobuzconnect to MyMusic Plugins Jun 10 13:47:05 volumio volumio[1095]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 10 13:47:05 volumio volumio[1095]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 10 13:47:05 volumio volumio[1095]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 10 13:47:06 volumio volumio[1095]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 10 13:47:06 volumio volumio[1095]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 10 13:47:06 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:06 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:06 volumio volumio[1095]: info: Starting MyVolumio Remote Streaming Endpoints Jun 10 13:47:06 volumio volumio[1095]: info: MyVolumio login type: Token Jun 10 13:47:06 volumio volumio[1095]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 10 13:47:06 volumio volumio[1095]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 10 13:47:07 volumio volumio[1432]: .................................................................................++++ Jun 10 13:47:08 volumio volumio[1095]: info: Starting Streaming Service Transparent Proxy Jun 10 13:47:08 volumio volumio[1095]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 10 13:47:08 volumio volumio[1095]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 10 13:47:08 volumio volumio[1095]: info: Streaming services startup Jun 10 13:47:08 volumio volumio[1095]: info: Starting Streaming Daemon Jun 10 13:47:08 volumio sudo[1646]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 10 13:47:08 volumio sudo[1646]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 10 13:47:08 volumio volumio[1095]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 10 13:47:08 volumio sudo[1646]: pam_unix(sudo:session): session closed for user root Jun 10 13:47:08 volumio volumio[1095]: info: Getting Spotify volume Jun 10 13:47:08 volumio volumio[1095]: error: Cannot start Volumio Streaming Daemon Jun 10 13:47:08 volumio volumio[1095]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 10 13:47:08 volumio volumio[1095]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 10 13:47:08 volumio volumio[1095]: info: Spotify volume: 100 Jun 10 13:47:08 volumio volumio[1095]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Jun 10 13:47:08 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:08 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:08 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:08 volumio volumio[1095]: SPOTIFY: SPOTIFY VOLUME 100 Jun 10 13:47:08 volumio volumio[1095]: SPOTIFY: VOLUMIO VOLUME 15 Jun 10 13:47:08 volumio volumio[1095]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 10 13:47:08 volumio volumio[1095]: info: Setting Spotify Volume from Volumio: 15 Jun 10 13:47:08 volumio volumio[1095]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 10 13:47:08 volumio volumio[1095]: STREAMING PROXY: Starting server on port 3245 Jun 10 13:47:08 volumio volumio[1095]: Node JS runtime: 14 Jun 10 13:47:09 volumio volumio[1095]: SPOTIFY: SETTING SPOTIFY VOLUME 15 Jun 10 13:47:09 volumio volumio[1095]: info: Sending Spotify command with payload to local API: /player/volume Jun 10 13:47:09 volumio go-librespot[1363]: time="2025-06-10T13:47:09+02:00" level=debug msg="update volume to 9830/65535" Jun 10 13:47:10 volumio volumio[1432]: ................................++++ Jun 10 13:47:10 volumio volumio[1432]: e is 65537 (0x010001) Jun 10 13:47:10 volumio volumio[1432]: writing RSA key Jun 10 13:47:10 volumio volumio[1095]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Jun 10 13:47:10 volumio go-librespot[1363]: time="2025-06-10T13:47:10+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 10 13:47:10 volumio go-librespot[1363]: time="2025-06-10T13:47:10+02:00" level=trace msg="emitting websocket event: volume" Jun 10 13:47:10 volumio volumio[1095]: SPOTIFY: received: {"type":"volume","data":{"value":15,"max":100}} Jun 10 13:47:10 volumio volumio[1095]: SPOTIFY: RECEIVED SPOTIFY VOLUME 15 Jun 10 13:47:11 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 10 13:47:11 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 10 13:47:11 volumio volumio[1095]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Jun 10 13:47:12 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 10 13:47:12 volumio volumio[1095]: info: MyVolumio token set successfully Jun 10 13:47:12 volumio volumio[1095]: info: MYVOLUMIO: Adding device Jun 10 13:47:12 volumio volumio[1095]: info: MYVOLUMIO: Evaluating Server Jun 10 13:47:12 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 10 13:47:13 volumio volumio[1095]: info: MyVolumio status changed Jun 10 13:47:13 volumio volumio[1095]: info: Streaming services startup Jun 10 13:47:13 volumio volumio[1095]: info: Starting Streaming Daemon Jun 10 13:47:13 volumio volumio[1095]: info: Removing browser output: myVolumio user plan is not superstar Jun 10 13:47:13 volumio volumio[1095]: info: Removing audio output: Jun 10 13:47:13 volumio volumio[1095]: info: Stoppping Tunnel 1 Jun 10 13:47:13 volumio sudo[1880]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 10 13:47:13 volumio sudo[1880]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 10 13:47:13 volumio sudo[1883]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jun 10 13:47:13 volumio sudo[1883]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 10 13:47:13 volumio sudo[1880]: pam_unix(sudo:session): session closed for user root Jun 10 13:47:13 volumio volumio[1095]: error: Cannot start Volumio Streaming Daemon Jun 10 13:47:13 volumio volumio[1095]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 10 13:47:13 volumio volumio[1095]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 10 13:47:13 volumio sudo[1883]: pam_unix(sudo:session): session closed for user root Jun 10 13:47:13 volumio volumio[1095]: info: Remote SSH Stopped Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::volumioGetVisibleSources Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:13 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 10 13:47:13 volumio volumio[1095]: info: Received Get System Info Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 10 13:47:13 volumio volumio[1095]: info: Discovery: Getting this device information Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:13 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:13 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:13 volumio volumio[1095]: info: Listing playlists Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:13 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 10 13:47:13 volumio volumio[1095]: info: Received Get System Info Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 10 13:47:13 volumio volumio[1095]: info: Discovery: Getting this device information Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:13 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:13 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 10 13:47:14 volumio volumio[1095]: info: Setting Geolocation for MyVolumio to eu5 Jun 10 13:47:14 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:14 volumio volumio[1095]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Jun 10 13:47:15 volumio volumio[1095]: info: Updating MyVolumio device info Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:15 volumio volumio[1095]: info: AutoStart - Plugin is starting Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::volumioGetQueue Jun 10 13:47:15 volumio volumio[1095]: info: CoreStateMachine::getQueue Jun 10 13:47:15 volumio volumio[1095]: info: CorePlayQueue::getQueue Jun 10 13:47:15 volumio volumio[1095]: info: AutoStart - start playing Jun 10 13:47:15 volumio volumio[1095]: info: AutoStart - start playing with no specific position Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::volumioPlay Jun 10 13:47:15 volumio volumio[1095]: info: CoreStateMachine::play index 0 Jun 10 13:47:15 volumio volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 13:47:15 volumio volumio[1095]: info: CoreStateMachine::stop Jun 10 13:47:15 volumio volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 13:47:15 volumio volumio[1095]: info: CoreStateMachine::play index undefined Jun 10 13:47:15 volumio volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 13:47:15 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:15 volumio volumio[1095]: info: CoreStateMachine::startPlaybackTimer Jun 10 13:47:15 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:15 volumio volumio[1095]: info: [1749556035319] ControllerWebradio::clearAddPlayTrack Jun 10 13:47:15 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop Jun 10 13:47:15 volumio volumio[1095]: info: sendMpdCommand stop took 1 milliseconds Jun 10 13:47:15 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand clear Jun 10 13:47:15 volumio volumio[1095]: info: Jun 10 13:47:15 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:15 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:15 volumio volumio[1095]: info: sendMpdCommand clear took 2 milliseconds Jun 10 13:47:15 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand load "http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0" Jun 10 13:47:15 volumio volumio[1095]: info: Jun 10 13:47:15 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:15 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:15 volumio volumio[1095]: info: Jun 10 13:47:15 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:15 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:15 volumio volumio[1095]: error: updateQueue error: null Jun 10 13:47:15 volumio volumio[1095]: info: ------------------------------ 5ms Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 10 13:47:15 volumio volumio[1095]: info: Received Get System Info Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 10 13:47:15 volumio volumio[1095]: info: Discovery: Getting this device information Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:15 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:15 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 10 13:47:16 volumio volumio[1095]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Jun 10 13:47:17 volumio systemd[1]: systemd-timedated.service: Succeeded. Jun 10 13:47:18 volumio volumio[1095]: info: MYVOLUMIO: Adding device Jun 10 13:47:18 volumio volumio[1095]: info: MYVOLUMIO: Evaluating Server Jun 10 13:47:19 volumio volumio[1095]: info: Setting Geolocation for MyVolumio to eu5 Jun 10 13:47:19 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:19 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:19 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:20 volumio volumio[1095]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Jun 10 13:47:20 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand add "http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0" Jun 10 13:47:20 volumio volumio[1095]: error: updateQueue error: null Jun 10 13:47:20 volumio volumio[1095]: error: updateQueue error: null Jun 10 13:47:20 volumio volumio[1095]: info: Jun 10 13:47:20 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:20 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:20 volumio volumio[1095]: info: ------------------------------ 4843ms Jun 10 13:47:20 volumio volumio[1095]: info: ------------------------------ 4843ms Jun 10 13:47:20 volumio volumio[1095]: info: sendMpdCommand add "http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0" took 2 milliseconds Jun 10 13:47:20 volumio volumio[1095]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 10 13:47:20 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand play Jun 10 13:47:20 volumio volumio[1095]: Upnp client error: Error: This socket has been ended by the other party Jun 10 13:47:20 volumio volumio[1095]: Upnp client error: Error: This socket has been ended by the other party Jun 10 13:47:20 volumio volumio[1095]: info: Jun 10 13:47:20 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:20 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:20 volumio volumio[1095]: info: Jun 10 13:47:20 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:20 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:20 volumio volumio[1095]: info: ------------------------------ 6ms Jun 10 13:47:20 volumio volumio[1095]: info: sendMpdCommand play took 6 milliseconds Jun 10 13:47:20 volumio volumio[1095]: info: ------------------------------ 4ms Jun 10 13:47:20 volumio volumio[1095]: info: ------------------------------ 3ms Jun 10 13:47:20 volumio volumio[1095]: info: Updating MyVolumio device info Jun 10 13:47:20 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:20 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:20 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:20 volumio volumio[1095]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 9 milliseconds Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 11 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 10 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 2 milliseconds Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","artist":null,"album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus stop Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 21ms Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 11 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 9 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 8 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 3 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 2 milliseconds Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","artist":null,"album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus play Jun 10 13:47:21 volumio volumio[1095]: info: Received an update from plugin. extracting info from payload Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","artist":null,"album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus play Jun 10 13:47:21 volumio volumio[1095]: info: Received an update from plugin. extracting info from payload Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 64ms Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 64ms Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:21 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 45 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 44 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 43 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","artist":null,"album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus play Jun 10 13:47:21 volumio volumio[1095]: info: Received an update from plugin. extracting info from payload Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","artist":null,"album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus play Jun 10 13:47:21 volumio volumio[1095]: info: Received an update from plugin. extracting info from payload Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","artist":null,"album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus play Jun 10 13:47:21 volumio volumio[1095]: info: Received an update from plugin. extracting info from payload Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 133ms Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 126ms Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 126ms Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: | Initialising... Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Current track does not have sufficient metadata: Missing artist. Not a composite title! RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Current track does not have sufficient metadata: Missing artist. Not a composite title! RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: RMF FM | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:21 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:47:21 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:47:21 volumio volumio[1095]: info: Jun 10 13:47:21 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 166ms Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 166 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 6ms Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 4 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 4ms Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand status took 4 milliseconds Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 17 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 16 milliseconds Jun 10 13:47:21 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 16 milliseconds Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:47:21 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Status Quo - In The Army Now","artist":"RMF FM","album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus play Jun 10 13:47:21 volumio volumio[1095]: info: Received an update from plugin. extracting info from payload Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1108,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Status Quo - In The Army Now","artist":"RMF FM","album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus play Jun 10 13:47:21 volumio volumio[1095]: info: Received an update from plugin. extracting info from payload Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:47:21 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:47:21 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1108,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Status Quo - In The Army Now","artist":"RMF FM","album":null,"uri":"http://www.rmfon.pl/tunein/tunein.php?host=rs201-krk-cyfronet.rmfstream.pl&mount=rmf_fm&secure=0","trackType":""} Jun 10 13:47:21 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus play Jun 10 13:47:21 volumio volumio[1095]: info: Received an update from plugin. extracting info from payload Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 236ms Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 75ms Jun 10 13:47:21 volumio volumio[1095]: info: ------------------------------ 74ms Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: RMF FM Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: undefined Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Split composite title into artist: Status Quo and title: In The Army Now Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Updating now playing Jun 10 13:47:21 volumio volumio[1095]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] starting new timer for 120000 milliseconds [RMF FM - Status Quo - In The Army Now]. Jun 10 13:47:21 volumio volumio[1095]: -------------------------------------------------// S T A R T I N G Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Timer started with time stamp 1749556041 Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: Status Quo - In The Army Now Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: Status Quo - In The Army Now Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: Status Quo - In The Army Now Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: Status Quo - In The Army Now Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:21 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: Status Quo - In The Army Now Jun 10 13:47:21 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:21 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:21 volumio volumio[1095]: info: touch_display: Setting screensaver timeout to 0 seconds. Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 10 13:47:21 volumio volumio[1095]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:21 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 10 13:47:25 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 10 13:47:25 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:25 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 10 13:47:25 volumio volumio-remote-updater[721]: No test mode Jun 10 13:47:25 volumio volumio-remote-updater[721]: No alpha test mode Jun 10 13:47:25 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Jun 10 13:47:25 volumio volumio[1095]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jun 10 13:47:25 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jun 10 13:47:26 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 10 13:47:26 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 10 13:47:26 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jun 10 13:47:26 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jun 10 13:47:26 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jun 10 13:47:26 volumio volumio[1095]: info: CoreCommandRouter::volumioGetBrowseSources Jun 10 13:47:26 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 10 13:47:28 volumio volumio[1095]: error: MyVolumio Plugin failed to authenticate in a timely fashion Jun 10 13:47:28 volumio volumio[1095]: info: Completed starting MyVolumio Plugin Jun 10 13:47:28 volumio volumio[1095]: [Metrics] CommandRouter: 40s 891.21ms Jun 10 13:47:28 volumio volumio[1095]: info: CoreCommandRouter::volumiosetStartupVolume Jun 10 13:47:28 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 10 13:47:28 volumio volumio[1095]: info: VolumeController:: Setting startup Volume 15 Jun 10 13:47:28 volumio volumio[1095]: info: VolumeController::SetAlsaVolume15 Jun 10 13:47:28 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 10 13:47:28 volumio volumio[1095]: info: CoreCommandRouter::Close All Modals sent Jun 10 13:47:28 volumio volumio[1095]: info: CoreCommandRouter::Close All Modals sent Jun 10 13:47:28 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:47:28 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:47:28 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:47:28 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:47:28 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: Status Quo - In The Army Now Jun 10 13:47:28 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:47:28 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:47:28 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:47:28 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15 Jun 10 13:47:28 volumio go-librespot[1363]: time="2025-06-10T13:47:28+02:00" level=trace msg="sent dealer ping" Jun 10 13:47:28 volumio go-librespot[1363]: time="2025-06-10T13:47:28+02:00" level=trace msg="received dealer pong" Jun 10 13:47:29 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jun 10 13:47:29 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 10 13:47:29 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jun 10 13:47:30 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 10 13:47:30 volumio volumio[1095]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 10 13:47:30 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 10 13:47:30 volumio volumio[1095]: info: Received Get System Version Jun 10 13:47:30 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 10 13:47:30 volumio volumio[1095]: info: Received Get System Info Jun 10 13:47:30 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 10 13:47:30 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 10 13:47:30 volumio volumio[1095]: info: Discovery: Getting this device information Jun 10 13:47:30 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:47:30 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 10 13:47:32 volumio ntpd[857]: Soliciting pool server 195.46.37.22 Jun 10 13:47:33 volumio ntpd[857]: Soliciting pool server 162.159.200.123 Jun 10 13:47:34 volumio ntpd[857]: Soliciting pool server 51.68.141.5 Jun 10 13:47:35 volumio volumio[1095]: info: BOOT COMPLETED Jun 10 13:47:35 volumio ntpd[857]: Soliciting pool server 80.68.234.117 Jun 10 13:47:35 volumio ntpd[857]: Soliciting pool server 193.59.134.156 Jun 10 13:47:36 volumio ntpd[857]: Soliciting pool server 213.222.217.11 Jun 10 13:47:36 volumio ntpd[857]: Soliciting pool server 194.146.251.100 Jun 10 13:47:36 volumio ntpd[857]: Soliciting pool server 91.212.242.21 Jun 10 13:47:37 volumio ntpd[857]: Soliciting pool server 156.17.20.254 Jun 10 13:47:37 volumio ntpd[857]: Soliciting pool server 85.115.212.251 Jun 10 13:47:37 volumio ntpd[857]: Soliciting pool server 91.212.242.20 Jun 10 13:47:38 volumio ntpd[857]: Soliciting pool server 85.115.212.254 Jun 10 13:47:38 volumio ntpd[857]: Soliciting pool server 2a0d:5440::24 Jun 10 13:47:39 volumio ntpd[857]: Soliciting pool server 91.210.128.220 Jun 10 13:47:41 volumio ntpd[857]: receive: Unexpected origin timestamp 0xebf299dc.d91e6ca9 does not match aorg 0000000000.00000000 from server@80.68.234.117 xmt 0xebf299dd.c18afc47 Jun 10 13:47:41 volumio ntpd[857]: receive: Unexpected origin timestamp 0xebf299dc.d91d2139 does not match aorg 0000000000.00000000 from server@193.59.134.156 xmt 0xebf299dd.c1b6763a Jun 10 13:47:41 volumio ntpd[857]: receive: Unexpected origin timestamp 0xebf299dc.d91b81ab does not match aorg 0000000000.00000000 from server@213.222.217.11 xmt 0xebf299dd.c29dbbd6 Jun 10 13:47:41 volumio ntpd[857]: Soliciting pool server 89.161.47.136 Jun 10 13:47:41 volumio ntpd[857]: receive: Unexpected origin timestamp 0xebf299dc.d920d6d1 does not match aorg 0000000000.00000000 from server@195.46.37.22 xmt 0xebf299dd.c360454c Jun 10 13:47:41 volumio ntpd[857]: receive: Unexpected origin timestamp 0xebf299dc.d918f657 does not match aorg 0000000000.00000000 from server@91.212.242.20 xmt 0xebf299dd.c20e6195 Jun 10 13:47:59 volumio go-librespot[1363]: time="2025-06-10T13:47:59+02:00" level=trace msg="sent dealer ping" Jun 10 13:47:59 volumio go-librespot[1363]: time="2025-06-10T13:47:59+02:00" level=trace msg="received dealer pong" Jun 10 13:48:12 volumio volumio[1095]: info: VolumeController::SetAlsaVolume20 Jun 10 13:48:12 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:12 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:12 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:12 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:12 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: Status Quo - In The Army Now Jun 10 13:48:12 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:48:12 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:48:12 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:48:12 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Jun 10 13:48:12 volumio volumio[1095]: SPOTIFY: SPOTIFY VOLUME 15 Jun 10 13:48:12 volumio volumio[1095]: SPOTIFY: VOLUMIO VOLUME 20 Jun 10 13:48:12 volumio volumio[1095]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 10 13:48:12 volumio volumio[1095]: info: Setting Spotify Volume from Volumio: 20 Jun 10 13:48:12 volumio volumio[1095]: info: VolumeController::SetAlsaVolume66 Jun 10 13:48:12 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:12 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:12 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:12 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:12 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Status Quo - In The Army Now | previous title: Status Quo - In The Army Now Jun 10 13:48:12 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:48:12 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:48:12 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:48:12 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jun 10 13:48:12 volumio volumio[1095]: SPOTIFY: SPOTIFY VOLUME 20 Jun 10 13:48:12 volumio volumio[1095]: SPOTIFY: VOLUMIO VOLUME 66 Jun 10 13:48:12 volumio volumio[1095]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 10 13:48:12 volumio volumio[1095]: info: Setting Spotify Volume from Volumio: 66 Jun 10 13:48:14 volumio volumio[1095]: SPOTIFY: SETTING SPOTIFY VOLUME 66 Jun 10 13:48:14 volumio volumio[1095]: info: Sending Spotify command with payload to local API: /player/volume Jun 10 13:48:14 volumio go-librespot[1363]: time="2025-06-10T13:48:14+02:00" level=debug msg="update volume to 43253/65535" Jun 10 13:48:15 volumio go-librespot[1363]: time="2025-06-10T13:48:15+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 10 13:48:15 volumio go-librespot[1363]: time="2025-06-10T13:48:15+02:00" level=trace msg="emitting websocket event: volume" Jun 10 13:48:15 volumio volumio[1095]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Jun 10 13:48:15 volumio volumio[1095]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Jun 10 13:48:23 volumio volumio[1095]: info: CoreCommandRouter::volumioGetQueue Jun 10 13:48:23 volumio volumio[1095]: info: CoreStateMachine::getQueue Jun 10 13:48:23 volumio volumio[1095]: info: CorePlayQueue::getQueue Jun 10 13:48:28 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: 80s80s , handleBrowseUri Jun 10 13:48:28 volumio volumio[1095]: info: [1749556108570] [80s80s] handleBrowseUri curUri: 80s80s Jun 10 13:48:28 volumio volumio[1095]: info: Preload queue cleared Jun 10 13:48:29 volumio go-librespot[1363]: time="2025-06-10T13:48:29+02:00" level=trace msg="sent dealer ping" Jun 10 13:48:29 volumio go-librespot[1363]: time="2025-06-10T13:48:29+02:00" level=trace msg="received dealer pong" Jun 10 13:48:30 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: 80s80s , handleBrowseUri Jun 10 13:48:30 volumio volumio[1095]: info: [1749556110504] [80s80s] handleBrowseUri curUri: 80s80s/nineties Jun 10 13:48:30 volumio volumio[1095]: info: [1749556110504] [80s80s] getRadioContent url: nineties Jun 10 13:48:30 volumio volumio[1095]: info: Preload queue cleared Jun 10 13:48:31 volumio volumio[1095]: info: Preload queue cleared Jun 10 13:48:31 volumio volumio[1095]: info: CoreCommandRouter::volumioReplaceandPlayItems Jun 10 13:48:31 volumio volumio[1095]: info: CoreStateMachine::ClearQueue Jun 10 13:48:31 volumio volumio[1095]: info: CoreStateMachine::stop Jun 10 13:48:31 volumio volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 13:48:31 volumio volumio[1095]: info: CoreStateMachine::stPlaybackTimer Jun 10 13:48:31 volumio volumio[1095]: info: CoreStateMachine::updateTrackBlock Jun 10 13:48:31 volumio volumio[1095]: info: CorePlayQueue::getTrackBlock Jun 10 13:48:31 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:31 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:31 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:31 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:31 volumio volumio[1095]: info: CoreStateMachine::serviceStop Jun 10 13:48:31 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:31 volumio volumio[1095]: info: CoreCommandRouter::serviceStop Jun 10 13:48:31 volumio volumio[1095]: info: [1749556111982] ControllerWebradio::stop Jun 10 13:48:31 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop Jun 10 13:48:31 volumio volumio[1095]: info: CorePlayQueue::clearPlayQueue Jun 10 13:48:31 volumio volumio[1095]: info: CorePlayQueue::saveQueue Jun 10 13:48:31 volumio volumio[1095]: info: CoreCommandRouter::volumioPushQueue Jun 10 13:48:31 volumio volumio[1095]: info: CoreStateMachine::addQueueItems Jun 10 13:48:31 volumio volumio[1095]: info: CorePlayQueue::addQueueItems Jun 10 13:48:31 volumio volumio[1095]: info: Preload queue cleared Jun 10 13:48:31 volumio volumio[1095]: info: Adding Item to queue: webnineties/4 Jun 10 13:48:31 volumio volumio[1095]: info: Exploding uri webnineties/4 in service 80s80s Jun 10 13:48:31 volumio volumio[1095]: info: [1749556111990] [80s80s] explodeUri: webnineties/4 Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::volumioPushQueue Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::saveQueue Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::updateTrackBlock Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrackBlock Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::volumioPlay Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::play index 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::stop Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::play index undefined Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::startPlaybackTimer Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: [1749556112035] [80s80s] clearAddPlayTrack url: http://streams.90s90s.de/techno/mp3-192/volumio Jun 10 13:48:32 volumio volumio[1095]: info: [1749556112035] [80s80s] getContentOfUrl started with url http://iris-90s90s.loverad.io/flow.json?station=261&count=2 Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] Undefined track duration or too short for scrobbling: undefined, 0 Jun 10 13:48:32 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: webradio | duration: undefined | title: RMF FM | previous title: Status Quo - In The Army Now Jun 10 13:48:32 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556041598 Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] stopping timer, playback has ended. Jun 10 13:48:32 volumio volumio[1095]: -------------------------------------------------// S T O P P I N G Jun 10 13:48:32 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand stop took 67 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand status took 26 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand status took 24 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand status took 22 milliseconds Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 8 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 8 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 7 milliseconds Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 69ms Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 67ms Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 65ms Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:32 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: 80s80s | duration: 1000 | title: 90s90s Techno | previous title: Status Quo - In The Army Now Jun 10 13:48:32 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: 1749556041598 Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:32 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: 80s80s | duration: 1000 | title: 90s90s Techno | previous title: Status Quo - In The Army Now Jun 10 13:48:32 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: 1749556041598 Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:32 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: 80s80s | duration: 1000 | title: 90s90s Techno | previous title: Status Quo - In The Army Now Jun 10 13:48:32 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: 1749556041598 Jun 10 13:48:32 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jun 10 13:48:32 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jun 10 13:48:32 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jun 10 13:48:32 volumio volumio[1095]: info: touch_display: Setting screensaver timeout to 120 seconds. Jun 10 13:48:32 volumio volumio[1095]: info: [1749556112290] [80s80s] received new event containing 2 songs. Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand stop Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand stop took 7 milliseconds Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand clear Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:32 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand clear took 2 milliseconds Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand consume 1 Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:32 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:32 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:32 volumio volumio[1095]: error: updateQueue error: null Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces state update: options Jun 10 13:48:32 volumio volumio[1095]: error: updateQueue error: null Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 10ms Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand consume 1 took 9 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 9ms Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 7ms Jun 10 13:48:32 volumio volumio[1095]: info: [1749556112315] [80s80s] adding url: http://streams.90s90s.de/techno/mp3-192/volumio Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand add "http://streams.90s90s.de/techno/mp3-192/volumio" Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces state update: options Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces state update: options Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:32 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand status took 11 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand add "http://streams.90s90s.de/techno/mp3-192/volumio" took 10 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand status took 7 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand status took 6 milliseconds Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand play Jun 10 13:48:32 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:32 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 52ms Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 78ms Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 75ms Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:32 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:32 volumio volumio[1095]: info: Jun 10 13:48:32 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:32 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 76ms Jun 10 13:48:32 volumio volumio[1095]: info: sendMpdCommand play took 64 milliseconds Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 3ms Jun 10 13:48:32 volumio volumio[1095]: info: ------------------------------ 3ms Jun 10 13:48:32 volumio volumio[1095]: info: [1749556112400] [80s80s] Pushing the next song state: Storm - Storm Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is1-ssl.mzstatic.com/image/thumb/Music124/v4/2c/b1/a2/2cb1a219-2240-def2-51fe-50dc5a16371c/source/600x600bb.jpg","name":"Storm - Storm","title":"Storm","artist":"90s90s Techno","album":"","streaming":true,"disableUiControls":true,"duration":"391","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Jun 10 13:48:32 volumio volumio[1095]: verbose: CURRENT POSITION 0 Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::syncState stateService play Jun 10 13:48:32 volumio volumio[1095]: info: CoreStateMachine::syncState currentStatus stop Jun 10 13:48:32 volumio volumio[1095]: info: [1749556112403] [80s80s] PlayNextTrack API delay: 30 Jun 10 13:48:32 volumio volumio[1095]: info: [1749556112419] [80s80s] Setting timer to: 391000 milliseconds. Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:32 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: 80s80s | duration: 1000 | title: 90s90s Techno | previous title: Status Quo - In The Army Now Jun 10 13:48:32 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: 1749556041598 Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:32 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: 80s80s | duration: 1000 | title: 90s90s Techno | previous title: Status Quo - In The Army Now Jun 10 13:48:32 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: 1749556041598 Jun 10 13:48:32 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:32 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: 80s80s | duration: 1000 | title: 90s90s Techno | previous title: Status Quo - In The Army Now Jun 10 13:48:32 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: 1749556041598 Jun 10 13:48:32 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jun 10 13:48:32 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jun 10 13:48:32 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:32 volumio volumio[1095]: info: CorePlayQueue::getTrack 1 Jun 10 13:48:34 volumio volumio[1095]: info: CoreCommandRouter::volumioGetState Jun 10 13:48:34 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:37 volumio volumio[1095]: info: Jun 10 13:48:37 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:37 volumio volumio[1095]: info: Jun 10 13:48:37 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:37 volumio volumio[1095]: info: Jun 10 13:48:37 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:37 volumio volumio[1095]: info: Jun 10 13:48:37 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand status took 4 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand status took 3 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand status took 3 milliseconds Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:37 volumio volumio[1095]: info: Jun 10 13:48:37 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:37 volumio volumio[1095]: info: Jun 10 13:48:37 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand status took 5 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 4 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 4 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 4 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand status took 3 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand status took 2 milliseconds Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:37 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:37 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:37 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:37 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:37 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:37 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:37 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:37 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:37 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:37 volumio volumio[1095]: info: ------------------------------ 15ms Jun 10 13:48:37 volumio volumio[1095]: info: ------------------------------ 14ms Jun 10 13:48:37 volumio volumio[1095]: info: ------------------------------ 12ms Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 4 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 3 milliseconds Jun 10 13:48:37 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 4 milliseconds Jun 10 13:48:37 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:37 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:37 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:37 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:37 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:37 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:37 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:37 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:37 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:37 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:37 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:37 volumio volumio[1095]: info: ------------------------------ 15ms Jun 10 13:48:37 volumio volumio[1095]: info: ------------------------------ 11ms Jun 10 13:48:37 volumio volumio[1095]: info: ------------------------------ 10ms Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 7ms Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand status took 5 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 5ms Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand status took 5 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 4ms Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand status took 3 milliseconds Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 8ms Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand status took 7 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 5 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 5 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 5 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 4ms Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand status took 3 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 4ms Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand status took 3 milliseconds Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:38 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:38 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:38 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:38 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:38 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:38 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:38 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:38 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:38 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 21ms Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 19ms Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 19ms Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 8 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 8 milliseconds Jun 10 13:48:38 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 4 milliseconds Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:38 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:38 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:38 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:38 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:38 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:38 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:38 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:38 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:38 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 20ms Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 16ms Jun 10 13:48:38 volumio volumio[1095]: info: ------------------------------ 15ms Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:38 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces system playlist update Jun 10 13:48:38 volumio volumio[1095]: info: Ignoring MPD Status Update Jun 10 13:48:38 volumio volumio[1095]: info: Jun 10 13:48:38 volumio volumio[1095]: ---------------------------- MPD announces state update: player Jun 10 13:48:38 volumio volumio[1095]: info: ControllerMpd::getState Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand status Jun 10 13:48:39 volumio volumio[1095]: info: ------------------------------ 7ms Jun 10 13:48:39 volumio volumio[1095]: info: sendMpdCommand status took 6 milliseconds Jun 10 13:48:39 volumio volumio[1095]: info: ------------------------------ 5ms Jun 10 13:48:39 volumio volumio[1095]: info: sendMpdCommand status took 4 milliseconds Jun 10 13:48:39 volumio volumio[1095]: info: ------------------------------ 4ms Jun 10 13:48:39 volumio volumio[1095]: info: sendMpdCommand status took 2 milliseconds Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::parseState Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 10 13:48:39 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 2 milliseconds Jun 10 13:48:39 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 2 milliseconds Jun 10 13:48:39 volumio volumio[1095]: info: sendMpdCommand playlistinfo took 1 milliseconds Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:39 volumio volumio[1095]: verbose: ControllerMpd::parseTrackInfo Jun 10 13:48:39 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:39 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:39 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:39 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:39 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:39 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:39 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:39 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:39 volumio volumio[1095]: info: ControllerMpd::pushState Jun 10 13:48:39 volumio volumio[1095]: info: CoreCommandRouter::servicePushState Jun 10 13:48:39 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:39 volumio volumio[1095]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Jun 10 13:48:39 volumio volumio[1095]: info: ------------------------------ 13ms Jun 10 13:48:39 volumio volumio[1095]: info: ------------------------------ 11ms Jun 10 13:48:39 volumio volumio[1095]: info: ------------------------------ 10ms Jun 10 13:48:43 volumio volumio[1095]: info: VolumeController::SetAlsaVolume72 Jun 10 13:48:43 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:43 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:43 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:43 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:43 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: 80s80s | duration: 391 | title: Storm - Storm | previous title: Status Quo - In The Army Now Jun 10 13:48:43 volumio volumio[1095]: info: =================> [timer] is active: false | can continue: false | timer started at: 1749556041598 Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] Current track has sufficient metadata: title (Storm - Storm) and artist (90s90s Techno) passed on explicitly Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] Updating now playing Jun 10 13:48:43 volumio volumio[1095]: error: [LastFM] plugin is not authenticated, please retry, or track info could not be determined (very rare) Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] starting new timer for 293250 milliseconds [90s90s Techno - Storm - Storm]. Jun 10 13:48:43 volumio volumio[1095]: -------------------------------------------------// S T A R T I N G Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] Timer started with time stamp 1749556123 Jun 10 13:48:43 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Jun 10 13:48:43 volumio volumio[1095]: SPOTIFY: SPOTIFY VOLUME 66 Jun 10 13:48:43 volumio volumio[1095]: SPOTIFY: VOLUMIO VOLUME 72 Jun 10 13:48:43 volumio volumio[1095]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 10 13:48:43 volumio volumio[1095]: info: Setting Spotify Volume from Volumio: 72 Jun 10 13:48:43 volumio volumio[1095]: info: touch_display: Setting screensaver timeout to 0 seconds. Jun 10 13:48:43 volumio volumio[1095]: info: VolumeController::SetAlsaVolume93 Jun 10 13:48:43 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:43 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:43 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:43 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:43 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: 80s80s | duration: 391 | title: Storm - Storm | previous title: Storm - Storm Jun 10 13:48:43 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556123222 Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:48:43 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:48:43 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 93 Jun 10 13:48:43 volumio volumio[1095]: SPOTIFY: SPOTIFY VOLUME 72 Jun 10 13:48:43 volumio volumio[1095]: SPOTIFY: VOLUMIO VOLUME 93 Jun 10 13:48:43 volumio volumio[1095]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 10 13:48:43 volumio volumio[1095]: info: Setting Spotify Volume from Volumio: 93 Jun 10 13:48:45 volumio volumio[1095]: info: VolumeController::SetAlsaVolume75 Jun 10 13:48:45 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:45 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:45 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:45 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:45 volumio volumio[1095]: info: [LastFM] using existing timer Jun 10 13:48:45 volumio volumio[1095]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: 80s80s | duration: 391 | title: Storm - Storm | previous title: Storm - Storm Jun 10 13:48:45 volumio volumio[1095]: info: =================> [timer] is active: true | can continue: false | timer started at: 1749556123222 Jun 10 13:48:45 volumio volumio[1095]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Jun 10 13:48:45 volumio volumio[1095]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Jun 10 13:48:45 volumio volumio[1095]: SPOTIFY: RECEIVED VOLUMIO VOLUME 75 Jun 10 13:48:45 volumio volumio[1095]: SPOTIFY: SPOTIFY VOLUME 93 Jun 10 13:48:45 volumio volumio[1095]: SPOTIFY: VOLUMIO VOLUME 75 Jun 10 13:48:45 volumio volumio[1095]: SPOTIFY: DELTA VOLUME ENOUGH: true Jun 10 13:48:45 volumio volumio[1095]: info: Setting Spotify Volume from Volumio: 75 Jun 10 13:48:46 volumio volumio[1095]: SPOTIFY: SETTING SPOTIFY VOLUME 75 Jun 10 13:48:46 volumio volumio[1095]: info: Sending Spotify command with payload to local API: /player/volume Jun 10 13:48:46 volumio go-librespot[1363]: time="2025-06-10T13:48:46+02:00" level=debug msg="update volume to 49151/65535" Jun 10 13:48:47 volumio go-librespot[1363]: time="2025-06-10T13:48:47+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 10 13:48:47 volumio go-librespot[1363]: time="2025-06-10T13:48:47+02:00" level=trace msg="emitting websocket event: volume" Jun 10 13:48:47 volumio volumio[1095]: SPOTIFY: received: {"type":"volume","data":{"value":75,"max":100}} Jun 10 13:48:47 volumio volumio[1095]: SPOTIFY: RECEIVED SPOTIFY VOLUME 75 Jun 10 13:48:52 volumio volumio[1095]: info: CoreCommandRouter::volumioRandom Jun 10 13:48:52 volumio volumio[1095]: info: CoreCommandRouter::writePlayerControls Jun 10 13:48:52 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:52 volumio volumio[1095]: info: CoreStateMachine::setRepeat true single false Jun 10 13:48:52 volumio volumio[1095]: info: CoreStateMachine::pushState Jun 10 13:48:52 volumio volumio[1095]: info: CorePlayQueue::getTrack 0 Jun 10 13:48:52 volumio volumio[1095]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 10 13:48:52 volumio volumio[1095]: info: CoreCommandRouter::volumioPushState Jun 10 13:48:52 volumio volumio[1095]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 10 13:48:52 volumio volumio[1095]: Error: Failed to convert napi value String into rust type `f64` on TimelineInfo.duration Jun 10 13:48:52 volumio volumio[1095]: at FerrumStreamingControlTechnology.updateStateOnPlayer (/data/plugins/user_interface/ferrum_streaming_control_technology/index.js:72:12) Jun 10 13:48:52 volumio volumio[1095]: at FerrumStreamingControlTechnology.pushState (/data/plugins/user_interface/ferrum_streaming_control_technology/index.js:183:10) Jun 10 13:48:52 volumio volumio[1095]: at /volumio/app/index.js:326:81 Jun 10 13:48:52 volumio volumio[1095]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Jun 10 13:48:52 volumio volumio[1095]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Jun 10 13:48:52 volumio volumio[1095]: at CoreCommandRouter.volumioPushState (/volumio/app/index.js:324:13) Jun 10 13:48:52 volumio volumio[1095]: at CoreStateMachine.pushState (/volumio/app/statemachine.js:530:22) Jun 10 13:48:52 volumio volumio[1095]: at CoreStateMachine.setRepeat (/volumio/app/statemachine.js:1426:10) Jun 10 13:48:52 volumio volumio[1095]: at CoreCommandRouter.volumioRepeat (/volumio/app/index.js:1594:28) Jun 10 13:48:52 volumio volumio[1095]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:284:33) Jun 10 13:48:52 volumio volumio[1095]: at Socket.emit (events.js:315:20) Jun 10 13:48:52 volumio volumio[1095]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Jun 10 13:48:52 volumio volumio[1095]: at processTicksAndRejections (internal/process/task_queues.js:75:11) { Jun 10 13:48:52 volumio volumio[1095]: code: 'NumberExpected' Jun 10 13:48:52 volumio volumio[1095]: } Jun 10 13:48:52 volumio volumio[1095]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 10 13:48:52 volumio sudo[2380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-10 13:47 Jun 10 13:48:52 volumio sudo[2380]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"