LastFM pluign causes playback & Queue to stop

tomstephens89 · December 11, 2019, 12:01pm

Just recently it seems that if I add some tracks to a queue, usually I add an album, playback will start, however will randomly stop after a track finishes. Sometimes this can happen after a couple of tracks, sometimes after just 1 track. There is plenty left in the queue. I do not have random or repeat enabled.

I also noticed the playback view skipped ahead to show the next track, whilst the current one was still playing. The playback stopped after the current track finished.

I Installed the Lastfm v1.2.9 plugin recently and this problem has been happening since then.

Disabling the plugin doesn’t help. However uninstalling and rebooting it fixes the issue.

Volumio 2.673

It seems like the lastfm plugin is broken.

Help!

How can I make the plugin developer aware of this?

tomstephens89 · December 14, 2019, 11:28am

Any acknowledgement? Have also PMed plugin dev.

tomstephens89 · December 14, 2019, 4:57pm

This happened again just now 4 tracks into an album.

Heres the last 500 lines of the log. Playback stopped at about 16:48. And it would seem Volumio is running through a startup procedure?

2019-12-14T16:44:34.881Z - info: Prefetching next song 2019-12-14T16:44:34.882Z - info: DOING PREFETCH IN MPD 2019-12-14T16:44:34.882Z - info: ControllerMpd::sendMpdCommand add "USB/SSD/FLAC_Collection/Led Zeppelin/How the West Was Won [Disc 1]/05. Led Zeppelin - Over The Hills And Far Away.flac" 2019-12-14T16:44:34.883Z - info: sending command... 2019-12-14T16:44:34.886Z - info: ---------------------------- MPD announces system playlist update 2019-12-14T16:44:34.892Z - info: Ignoring MPD Status Update 2019-12-14T16:44:34.893Z - info: parsing response... 2019-12-14T16:44:34.895Z - info: ControllerMpd::sendMpdCommand consume 1 2019-12-14T16:44:34.896Z - info: sending command... 2019-12-14T16:44:34.899Z - info: ------------------------------ 13ms 2019-12-14T16:44:34.900Z - info: parsing response... 2019-12-14T16:44:39.151Z - info: CoreStateMachine::startPlaybackTimer 2019-12-14T16:44:39.152Z - info: CorePlayQueue::getTrack 4 2019-12-14T16:44:40.196Z - info: ---------------------------- MPD announces system playlist update 2019-12-14T16:44:40.197Z - info: Ignoring MPD Status Update 2019-12-14T16:44:40.197Z - info: ---------------------------- MPD announces state update: player 2019-12-14T16:44:40.198Z - info: ControllerMpd::getState 2019-12-14T16:44:40.199Z - info: ControllerMpd::sendMpdCommand status 2019-12-14T16:44:40.200Z - info: sending command... 2019-12-14T16:44:40.202Z - info: ------------------------------ 5ms 2019-12-14T16:44:40.202Z - info: parsing response... 2019-12-14T16:44:40.203Z - info: ControllerMpd::parseState 2019-12-14T16:44:40.204Z - info: ControllerMpd::sendMpdCommand playlistinfo 2019-12-14T16:44:40.204Z - info: sending command... 2019-12-14T16:44:40.206Z - info: parsing response... 2019-12-14T16:44:40.206Z - info: ControllerMpd::parseTrackInfo 2019-12-14T16:44:40.207Z - info: ControllerMpd::pushState 2019-12-14T16:44:40.207Z - info: CoreCommandRouter::servicePushState 2019-12-14T16:44:40.208Z - info: CoreStateMachine::syncState 2019-12-14T16:44:40.208Z - info: CorePlayQueue::getTrack 4 2019-12-14T16:44:40.208Z - info: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":308,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"Over The Hills And Far Away","artist":"Led Zeppelin","album":"How the West Was Won","uri":"USB/SSD/FLAC_Collection/Led Zeppelin/How the West Was Won [Disc 1]/05. Led Zeppelin - Over The Hills And Far Away.flac","trackType":"flac"} 2019-12-14T16:44:40.209Z - info: CURRENT POSITION 4 2019-12-14T16:44:40.209Z - info: CoreStateMachine::syncState stateService play 2019-12-14T16:44:40.209Z - info: CoreStateMachine::syncState currentStatus play 2019-12-14T16:44:40.210Z - info: Received an update from plugin. extracting info from payload 2019-12-14T16:44:40.210Z - info: CoreStateMachine::pushState 2019-12-14T16:44:40.210Z - info: CoreStateMachine::getState 2019-12-14T16:44:40.211Z - info: CorePlayQueue::getTrack 4 2019-12-14T16:44:40.211Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:44:40.211Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:44:40.281Z - info: CoreStateMachine::pushState 2019-12-14T16:44:40.282Z - info: CoreStateMachine::getState 2019-12-14T16:44:40.282Z - info: CorePlayQueue::getTrack 4 2019-12-14T16:44:40.283Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:44:40.283Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:44:40.425Z - info: ------------------------------ 227ms 2019-12-14T16:44:42.156Z - info: [LastFM] corrected track title from: Over The Hills And Far Away to: Over the Hills and Far Away 2019-12-14T16:47:16.224Z - info: Tunnel connection is inactive, restarting it 2019-12-14T16:47:16.225Z - info: Starting Tunnel 1 2019-12-14T16:47:16.226Z - info: Starting Tunnel Connection Checker 2019-12-14T16:47:16.447Z - info: Remote SSH Started 2019-12-14T16:47:16.519Z - info: CoreCommandRouter::volumioGetState 2019-12-14T16:47:16.520Z - info: CoreStateMachine::getState 2019-12-14T16:47:16.520Z - info: CorePlayQueue::getTrack 4 2019-12-14T16:48:38.983Z - info: ------------------------------------------- 2019-12-14T16:48:38.989Z - info: ----- Volumio2 ---- 2019-12-14T16:48:38.990Z - info: ------------------------------------------- 2019-12-14T16:48:38.990Z - info: ----- System startup ---- 2019-12-14T16:48:38.990Z - info: ------------------------------------------- 2019-12-14T16:48:39.215Z - info: MYVOLUMIO Environment detected 2019-12-14T16:48:41.245Z - info: Plugin folders cleanup 2019-12-14T16:48:41.246Z - info: Scanning into folder /volumio/app/plugins/ 2019-12-14T16:48:41.247Z - info: Scanning category audio_interface 2019-12-14T16:48:41.249Z - info: Scanning category miscellanea 2019-12-14T16:48:41.251Z - info: Scanning category music_service 2019-12-14T16:48:41.253Z - info: Scanning category plugins.json 2019-12-14T16:48:41.254Z - info: Scanning category system_controller 2019-12-14T16:48:41.257Z - info: Scanning category user_interface 2019-12-14T16:48:41.259Z - info: Scanning into folder /data/plugins/ 2019-12-14T16:48:41.260Z - info: Scanning category miscellanea 2019-12-14T16:48:41.261Z - info: Plugin folders cleanup completed 2019-12-14T16:48:41.264Z - info: ------------------------------------------- 2019-12-14T16:48:41.264Z - info: ----- Core plugins startup ---- 2019-12-14T16:48:41.265Z - info: ------------------------------------------- 2019-12-14T16:48:41.267Z - info: Loading plugins from folder /volumio/app/plugins/ 2019-12-14T16:48:41.273Z - info: Adding plugin upnp to MyMusic Plugins 2019-12-14T16:48:41.277Z - info: Adding plugin airplay_emulation to MyMusic Plugins 2019-12-14T16:48:41.282Z - info: Adding plugin upnp_browser to MyMusic Plugins 2019-12-14T16:48:41.287Z - info: Loading plugins from folder /data/plugins/ 2019-12-14T16:48:41.293Z - info: Loading plugin "system"... 2019-12-14T16:48:41.345Z - info: Loading plugin "appearance"... 2019-12-14T16:48:43.206Z - info: Loading plugin "network"... 2019-12-14T16:48:44.041Z - info: Loading plugin "services"... 2019-12-14T16:48:44.051Z - info: Loading plugin "alsa_controller"... 2019-12-14T16:48:44.183Z - info: Loading plugin "wizard"... 2019-12-14T16:48:44.203Z - info: Loading plugin "volumio_command_line_client"... 2019-12-14T16:48:44.273Z - info: Loading plugin "upnp"... 2019-12-14T16:48:44.284Z - info: [1576342124284] Starting Upmpd Daemon 2019-12-14T16:48:44.290Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-14T16:48:44.294Z - info: Loading plugin "my_music"... 2019-12-14T16:48:44.309Z - info: Loading plugin "mpd"... 2019-12-14T16:48:45.102Z - info: Loading plugin "upnp_browser"... 2019-12-14T16:48:45.938Z - info: Loading plugin "networkfs"... 2019-12-14T16:48:46.248Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-14T16:48:46.252Z - info: Loading plugin "alarm-clock"... 2019-12-14T16:48:46.657Z - info: Loading plugin "airplay_emulation"... 2019-12-14T16:48:46.709Z - info: Starting Shairport Sync 2019-12-14T16:48:46.712Z - info: Loading plugin "last_100"... 2019-12-14T16:48:46.726Z - info: Loading plugin "webradio"... 2019-12-14T16:48:46.962Z - info: Loading plugin "i2s_dacs"... 2019-12-14T16:48:46.990Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:48:46.995Z - info: Loading plugin "volumiodiscovery"... 2019-12-14T16:48:47.104Z - info: Applying required configuration parameters for plugin volumiodiscovery 2019-12-14T16:48:47.165Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-14T16:48:47.167Z - info: Loading plugin "outputs"... 2019-12-14T16:48:47.183Z - info: Loading plugin "albumart"... 2019-12-14T16:48:47.231Z - info: Plugin example_plugin is not enabled 2019-12-14T16:48:47.233Z - info: Loading plugin "inputs"... 2019-12-14T16:48:47.253Z - info: Loading plugin "updater_comm"... 2019-12-14T16:48:47.621Z - info: Plugin mpdemulation is not enabled 2019-12-14T16:48:47.623Z - info: Loading plugin "rest_api"... 2019-12-14T16:48:47.699Z - info: Loading plugin "websocket"... 2019-12-14T16:48:47.807Z - info: Loading plugin "lastfm"... 2019-12-14T16:48:50.027Z - info: [LastFM] scrobbler initiated! 2019-12-14T16:48:50.028Z - info: [LastFM] extended logging: false 2019-12-14T16:48:50.029Z - info: [LastFM] try scrobble stream/radio plays: true 2019-12-14T16:48:50.038Z - info: ___________ START PLUGINS ___________ 2019-12-14T16:48:50.049Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-14T16:48:50.052Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T16:48:50.054Z - info: [1576342130053] CoreMusicLibrary::Adding element Media Servers 2019-12-14T16:48:50.056Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:48:50.487Z - info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 2019-12-14T16:48:50.565Z - info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 2019-12-14T16:48:50.568Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T16:48:50.569Z - info: [1576342130568] CoreMusicLibrary::Adding element Last_100 2019-12-14T16:48:50.570Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:48:50.574Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T16:48:50.575Z - info: [1576342130574] CoreMusicLibrary::Adding element Webradio 2019-12-14T16:48:50.575Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:48:50.583Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion 2019-12-14T16:48:50.595Z - info: Performing onStart action 2019-12-14T16:48:50.596Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T16:48:50.597Z - info: [1576342130596] CoreMusicLibrary::Adding element LastFM 2019-12-14T16:48:50.597Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:48:50.602Z - info: ------------------------------------------- 2019-12-14T16:48:50.603Z - info: ----- MyVolumio plugins startup ---- 2019-12-14T16:48:50.603Z - info: ------------------------------------------- 2019-12-14T16:48:50.605Z - info: [MyVolumio PluginManager] Fetching plans data.... 2019-12-14T16:48:50.621Z - info: Loading i18n strings for locale en 2019-12-14T16:48:50.632Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:48:50.672Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-14T16:48:50.676Z - info: CoreCommandRouter::initPlayerControls 2019-12-14T16:48:50.734Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T16:48:50.736Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getAlsaCards 2019-12-14T16:48:50.822Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T16:48:50.823Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T16:48:50.823Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T16:48:50.824Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T16:48:50.824Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T16:48:50.845Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-14T16:48:50.850Z - info: BOOT COMPLETED 2019-12-14T16:48:50.852Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:48:50.936Z - info: CoreCommandRouter::Close All Modals sent 2019-12-14T16:48:50.938Z - info: CoreCommandRouter::Close All Modals sent 2019-12-14T16:48:51.093Z - info: CoreStateMachine::resetVolumioState 2019-12-14T16:48:51.094Z - info: CoreStateMachine::getcurrentVolume 2019-12-14T16:48:51.095Z - info: CoreCommandRouter::volumioRetrievevolume 2019-12-14T16:48:51.109Z - info: CoreStateMachine::pushState 2019-12-14T16:48:51.113Z - info: CoreStateMachine::getState 2019-12-14T16:48:51.114Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:48:51.116Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:48:51.117Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:48:51.739Z - info: Volumio called home 2019-12-14T16:48:51.746Z - info: Setting Device type: Raspberry PI 2019-12-14T16:48:51.758Z - info: MPD running with PID719 ,establishing connection 2019-12-14T16:48:52.064Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable 2019-12-14T16:48:52.153Z - info: CoreCommandRouter::executeOnPlugin: raat , onStop 2019-12-14T16:48:52.157Z - info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect 2019-12-14T16:48:52.171Z - info: Reloading queue from file 2019-12-14T16:48:52.361Z - info: CoreStateMachine::setRepeat false single undefined 2019-12-14T16:48:52.362Z - info: CoreStateMachine::pushState 2019-12-14T16:48:52.363Z - info: CoreStateMachine::getState 2019-12-14T16:48:52.364Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:48:52.365Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:48:52.366Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:48:52.373Z - info: CoreStateMachine::setRandom false 2019-12-14T16:48:52.373Z - info: CoreStateMachine::pushState 2019-12-14T16:48:52.374Z - info: CoreStateMachine::getState 2019-12-14T16:48:52.375Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:48:52.376Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:48:52.376Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:48:52.875Z - info: Shairport-Sync Started 2019-12-14T16:48:52.884Z - info: Shairport-Sync Started 2019-12-14T16:48:52.908Z - info: mDNS: Found device Volumio 2019-12-14T16:48:53.042Z - info: mDNS: Found device Volumio 2019-12-14T16:49:04.064Z - info: CoreCommandRouter::volumioGetState 2019-12-14T16:49:04.065Z - info: CoreStateMachine::getState 2019-12-14T16:49:04.066Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:49:04.152Z - info: Upmpdcli Daemon Started 2019-12-14T16:49:04.576Z - info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar 2019-12-14T16:49:04.578Z - info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar 2019-12-14T16:49:04.578Z - info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar 2019-12-14T16:49:04.579Z - info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar 2019-12-14T16:49:04.580Z - info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso 2019-12-14T16:49:04.581Z - info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso 2019-12-14T16:49:04.586Z - info: Adding plugin bluetooth to MyMusic Plugins 2019-12-14T16:49:04.589Z - info: Adding plugin cd_controller to MyMusic Plugins 2019-12-14T16:49:04.597Z - info: Adding plugin smart_inputs to MyMusic Plugins 2019-12-14T16:49:04.603Z - info: [MyVolumio PluginManager] Loading plugin "my_volumio"... 2019-12-14T16:49:08.727Z - info: [MyVolumio PluginManager] Loading plugin "streaming_services"... 2019-12-14T16:49:11.345Z - info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded 2019-12-14T16:49:11.348Z - info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio 2019-12-14T16:49:11.350Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:11.351Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:11.355Z - info: Starting MyVolumio Remote Streaming Endpoints 2019-12-14T16:49:11.407Z - info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded 2019-12-14T16:49:11.409Z - info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services 2019-12-14T16:49:11.412Z - info: Streaming services startup 2019-12-14T16:49:11.420Z - info: Starting Streaming Daemon 2019-12-14T16:49:11.473Z - info: [MyVolumio PluginManager] MyVolumio plugin successfully started 2019-12-14T16:49:11.848Z - error: MyVolumio Custom Token format not valid, refreshing it 2019-12-14T16:49:13.323Z - info: MYVOLUMIO SUCCESSFULLY LOGGED IN 2019-12-14T16:49:13.326Z - info: MYVOLUMIO: Adding device 2019-12-14T16:49:13.327Z - info: MYVOLUMIO: Evaluating Server 2019-12-14T16:49:14.900Z - info: [MyVolumio PluginManager] Subscribed plan changed to virtuoso 2019-12-14T16:49:14.905Z - info: Removing browser output: myVolumio user plan is not superstar 2019-12-14T16:49:14.907Z - info: Removing audio output: 2019-12-14T16:49:14.993Z - info: Setting Geolocation for MyVolumio to eu1 2019-12-14T16:49:14.997Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:14.998Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:14.999Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:15.048Z - info: Fetching Streaming Services browse cache 2019-12-14T16:49:15.064Z - info: Remote config written successfully 2019-12-14T16:49:15.066Z - info: Starting Tunnel 1 2019-12-14T16:49:15.070Z - info: Starting Tunnel Connection Checker 2019-12-14T16:49:15.088Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesTIDAL 2019-12-14T16:49:15.091Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:49:15.115Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesQOBUZ 2019-12-14T16:49:15.116Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:49:15.411Z - info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... 2019-12-14T16:49:15.421Z - info: MyVolumio status changed 2019-12-14T16:49:15.422Z - info: Streaming services startup 2019-12-14T16:49:15.426Z - info: Re-Starting Streaming Daemon 2019-12-14T16:49:15.725Z - info: Remote SSH Started 2019-12-14T16:49:16.046Z - info: Updating MyVolumio device info 2019-12-14T16:49:16.047Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:16.048Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:16.049Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:16.108Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid 2019-12-14T16:49:16.115Z - error: [MyVolumio PluginManager] Cache data is invalid! 2019-12-14T16:49:16.548Z - info: CoreCommandRouter::volumioGetState 2019-12-14T16:49:16.551Z - info: CoreStateMachine::getState 2019-12-14T16:49:16.553Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:49:18.014Z - info: [MyVolumio PluginManager] Loading plugin "bluetooth"... 2019-12-14T16:49:18.477Z - info: [1576342158476] Starting BluetoothController 2019-12-14T16:49:18.672Z - info: [MyVolumio PluginManager] Loading plugin "cd_controller"... 2019-12-14T16:49:18.845Z - info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth 2019-12-14T16:49:18.847Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-14T16:49:18.892Z - info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller 2019-12-14T16:49:18.900Z - info: Adding CD REST API Endpoints 2019-12-14T16:49:18.903Z - info: Adding detectCD REST Endpoint for plugin: music_service/cd_controller 2019-12-14T16:49:18.904Z - info: Adding cdRemove REST Endpoint for plugin: music_service/cd_controller 2019-12-14T16:49:18.905Z - info: Adding cdPostScan REST Endpoint for plugin: music_service/cd_controller 2019-12-14T16:49:18.905Z - info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller 2019-12-14T16:49:18.907Z - info: Detecting CD presence 2019-12-14T16:49:18.919Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid 2019-12-14T16:49:19.354Z - info: Bluetooth name changed to Volumio 2019-12-14T16:49:19.391Z - info: Fetching Streaming Services browse cache 2019-12-14T16:49:19.598Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T16:49:19.599Z - info: [1576342159598] CoreMusicLibrary::Adding element TIDAL 2019-12-14T16:49:19.600Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:49:19.614Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesQOBUZ 2019-12-14T16:49:19.615Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:49:20.645Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion 2019-12-14T16:49:20.648Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T16:49:22.049Z - info: Volumio BT Module successfully started 2019-12-14T16:49:48.301Z - info: ---------------------------- MPD announces system playlist update 2019-12-14T16:49:48.305Z - info: Ignoring MPD Status Update 2019-12-14T16:49:48.306Z - info: ---------------------------- MPD announces state update: player 2019-12-14T16:49:48.310Z - info: ControllerMpd::getState 2019-12-14T16:49:48.312Z - info: ControllerMpd::sendMpdCommand status 2019-12-14T16:49:48.315Z - info: sending command... 2019-12-14T16:49:48.318Z - info: 2019-12-14T16:49:48.321Z - info: ------------------------------ 21ms 2019-12-14T16:49:48.322Z - info: parsing response... 2019-12-14T16:49:48.328Z - info: ControllerMpd::parseState 2019-12-14T16:49:48.330Z - info: ControllerMpd::pushState 2019-12-14T16:49:48.331Z - info: CoreCommandRouter::servicePushState 2019-12-14T16:49:48.339Z - info: CoreStateMachine::syncState 2019-12-14T16:49:48.340Z - info: CoreStateMachine::pushState 2019-12-14T16:49:48.340Z - info: CoreStateMachine::getState 2019-12-14T16:49:48.341Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:49:48.341Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:49:48.342Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:49:48.391Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:49:48.392Z - info: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} 2019-12-14T16:49:48.393Z - info: CURRENT POSITION 0 2019-12-14T16:49:48.394Z - info: CoreStateMachine::syncState stateService stop 2019-12-14T16:49:48.395Z - info: CoreStateMachine::syncState currentStatus stop 2019-12-14T16:49:48.395Z - info: CoreStateMachine::pushState 2019-12-14T16:49:48.396Z - info: CoreStateMachine::getState 2019-12-14T16:49:48.397Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:49:48.398Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:49:48.398Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:49:48.451Z - info: No code 2019-12-14T16:49:48.452Z - info: CoreStateMachine::pushState 2019-12-14T16:49:48.453Z - info: CoreStateMachine::getState 2019-12-14T16:49:48.453Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:49:48.454Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:49:48.455Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:49:48.524Z - info: ------------------------------ 219ms 2019-12-14T16:50:07.716Z - info: CoreCommandRouter::volumioGetVisibleSources 2019-12-14T16:50:07.718Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:50:07.737Z - info: CoreCommandRouter::volumioGetState 2019-12-14T16:50:07.738Z - info: CoreStateMachine::getState 2019-12-14T16:50:07.738Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:50:07.789Z - info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings 2019-12-14T16:50:07.792Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-14T16:50:07.794Z - info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard 2019-12-14T16:50:07.795Z - info: CoreCommandRouter::executeOnPlugin: system , getShowWizard 2019-12-14T16:50:07.844Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom 2019-12-14T16:50:07.846Z - info: Listing playlists 2019-12-14T16:50:09.394Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus 2019-12-14T16:50:09.410Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken 2019-12-14T16:50:13.896Z - info: CoreCommandRouter::volumioGetQueue 2019-12-14T16:50:13.897Z - info: CoreStateMachine::getQueue 2019-12-14T16:50:13.898Z - info: CorePlayQueue::getQueue 2019-12-14T16:50:29.614Z - info: CoreCommandRouter::volumioClearQueue 2019-12-14T16:50:29.615Z - info: CoreStateMachine::ClearQueue 2019-12-14T16:50:29.617Z - info: CoreStateMachine::stop 2019-12-14T16:50:29.619Z - info: CoreStateMachine::setConsumeUpdateService undefined 2019-12-14T16:50:29.621Z - info: CorePlayQueue::clearPlayQueue 2019-12-14T16:50:29.623Z - info: CorePlayQueue::saveQueue 2019-12-14T16:50:29.626Z - info: CoreStateMachine::pushEmptyState 2019-12-14T16:50:29.627Z - info: CoreCommandRouter::volumioPushState 2019-12-14T16:50:29.628Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T16:50:29.679Z - info: CoreCommandRouter::volumioPushQueue 2019-12-14T16:53:15.094Z - info: Tunnel connection is inactive, restarting it 2019-12-14T16:53:15.095Z - info: Starting Tunnel 1 2019-12-14T16:53:15.097Z - info: Starting Tunnel Connection Checker 2019-12-14T16:53:15.317Z - info: Remote SSH Started 2019-12-14T16:53:15.416Z - info: CoreCommandRouter::volumioGetState 2019-12-14T16:53:15.417Z - info: CoreStateMachine::getState 2019-12-14T16:53:15.418Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:56:15.109Z - info: Tunnel connection is inactive, restarting it 2019-12-14T16:56:15.110Z - info: Starting Tunnel 1 2019-12-14T16:56:15.111Z - info: Starting Tunnel Connection Checker 2019-12-14T16:56:15.306Z - info: Remote SSH Started 2019-12-14T16:56:15.372Z - info: CoreCommandRouter::volumioGetState 2019-12-14T16:56:15.373Z - info: CoreStateMachine::getState 2019-12-14T16:56:15.374Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:56:38.733Z - info: CoreCommandRouter::volumioGetState 2019-12-14T16:56:38.734Z - info: CoreStateMachine::getState 2019-12-14T16:56:38.734Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:56:38.821Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom 2019-12-14T16:56:38.828Z - info: Listing playlists 2019-12-14T16:56:38.829Z - info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings 2019-12-14T16:56:38.831Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-14T16:56:38.833Z - info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard 2019-12-14T16:56:38.834Z - info: CoreCommandRouter::executeOnPlugin: system , getShowWizard 2019-12-14T16:56:39.734Z - info: CoreCommandRouter::volumioGetQueue 2019-12-14T16:56:39.735Z - info: CoreStateMachine::getQueue 2019-12-14T16:56:39.735Z - info: CorePlayQueue::getQueue 2019-12-14T16:56:39.762Z - info: CoreCommandRouter::volumioGetVisibleSources 2019-12-14T16:56:39.763Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:56:40.397Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus 2019-12-14T16:56:41.762Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus 2019-12-14T16:56:54.725Z - info: CoreCommandRouter::volumioGetVisibleSources 2019-12-14T16:56:54.726Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T16:56:54.734Z - info: CoreCommandRouter::volumioGetState 2019-12-14T16:56:54.735Z - info: CoreStateMachine::getState 2019-12-14T16:56:54.736Z - info: CorePlayQueue::getTrack 0 2019-12-14T16:56:54.812Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom 2019-12-14T16:56:54.812Z - info: Listing playlists 2019-12-14T16:56:54.814Z - info: CoreCommandRouter::volumioGetQueue 2019-12-14T16:56:54.814Z - info: CoreStateMachine::getQueue 2019-12-14T16:56:54.815Z - info: CorePlayQueue::getQueue

tomstephens89 · December 14, 2019, 5:08pm

And again. This time after the first track in queue finished. 17:07 ish. This time with the lastfm debug log enabled.

Heres the last 250 lines, and again you see a startup procedure?

volumio@volumio:/var/log$ tail volumio.log -n 250 2019-12-14T17:06:24.492Z - info: Loading plugin "alsa_controller"... 2019-12-14T17:06:24.620Z - info: Loading plugin "wizard"... 2019-12-14T17:06:24.637Z - info: Loading plugin "volumio_command_line_client"... 2019-12-14T17:06:24.707Z - info: Loading plugin "upnp"... 2019-12-14T17:06:24.719Z - info: [1576343184718] Starting Upmpd Daemon 2019-12-14T17:06:24.724Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-14T17:06:24.728Z - info: Loading plugin "my_music"... 2019-12-14T17:06:24.740Z - info: Loading plugin "mpd"... 2019-12-14T17:06:25.517Z - info: Loading plugin "upnp_browser"... 2019-12-14T17:06:26.323Z - info: Loading plugin "networkfs"... 2019-12-14T17:06:26.603Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-14T17:06:26.605Z - info: Loading plugin "alarm-clock"... 2019-12-14T17:06:26.990Z - info: Loading plugin "airplay_emulation"... 2019-12-14T17:06:27.040Z - info: Starting Shairport Sync 2019-12-14T17:06:27.042Z - info: Loading plugin "last_100"... 2019-12-14T17:06:27.057Z - info: Loading plugin "webradio"... 2019-12-14T17:06:27.286Z - info: Loading plugin "i2s_dacs"... 2019-12-14T17:06:27.311Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:27.316Z - info: Loading plugin "volumiodiscovery"... 2019-12-14T17:06:27.404Z - info: Applying required configuration parameters for plugin volumiodiscovery 2019-12-14T17:06:27.465Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-14T17:06:27.466Z - info: Loading plugin "outputs"... 2019-12-14T17:06:27.483Z - info: Loading plugin "albumart"... 2019-12-14T17:06:27.534Z - info: Plugin example_plugin is not enabled 2019-12-14T17:06:27.536Z - info: Loading plugin "inputs"... 2019-12-14T17:06:27.557Z - info: Loading plugin "updater_comm"... 2019-12-14T17:06:27.944Z - info: Plugin mpdemulation is not enabled 2019-12-14T17:06:27.945Z - info: Loading plugin "rest_api"... 2019-12-14T17:06:28.019Z - info: Loading plugin "websocket"... 2019-12-14T17:06:28.126Z - info: Loading plugin "lastfm"... 2019-12-14T17:06:29.921Z - info: [LastFM] supported song services: ["mpd","airplay","volspotconnect","volspotconnect2","spop"] 2019-12-14T17:06:29.922Z - info: [LastFM] supported streaming services: ["webradio","radio_paradise","80s80s"] 2019-12-14T17:06:29.922Z - info: [LastFM] scrobbler initiated! 2019-12-14T17:06:29.923Z - info: [LastFM] extended logging: true 2019-12-14T17:06:29.924Z - info: [LastFM] try scrobble stream/radio plays: true 2019-12-14T17:06:29.933Z - info: ___________ START PLUGINS ___________ 2019-12-14T17:06:29.943Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-14T17:06:29.946Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T17:06:29.948Z - info: [1576343189947] CoreMusicLibrary::Adding element Media Servers 2019-12-14T17:06:29.950Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:30.159Z - info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 2019-12-14T17:06:30.264Z - info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 2019-12-14T17:06:30.267Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T17:06:30.268Z - info: [1576343190268] CoreMusicLibrary::Adding element Last_100 2019-12-14T17:06:30.270Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:30.275Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T17:06:30.276Z - info: [1576343190275] CoreMusicLibrary::Adding element Webradio 2019-12-14T17:06:30.277Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:30.286Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion 2019-12-14T17:06:30.303Z - info: Performing onStart action 2019-12-14T17:06:30.305Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T17:06:30.306Z - info: [1576343190305] CoreMusicLibrary::Adding element LastFM 2019-12-14T17:06:30.308Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:30.314Z - info: ------------------------------------------- 2019-12-14T17:06:30.314Z - info: ----- MyVolumio plugins startup ---- 2019-12-14T17:06:30.315Z - info: ------------------------------------------- 2019-12-14T17:06:30.317Z - info: [MyVolumio PluginManager] Fetching plans data.... 2019-12-14T17:06:30.337Z - info: Loading i18n strings for locale en 2019-12-14T17:06:30.350Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:30.393Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-14T17:06:30.398Z - info: CoreCommandRouter::initPlayerControls 2019-12-14T17:06:30.505Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T17:06:30.509Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getAlsaCards 2019-12-14T17:06:30.610Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T17:06:30.613Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T17:06:30.616Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T17:06:30.620Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T17:06:30.623Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-14T17:06:30.646Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-14T17:06:30.654Z - info: BOOT COMPLETED 2019-12-14T17:06:30.657Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:30.736Z - info: CoreCommandRouter::Close All Modals sent 2019-12-14T17:06:30.737Z - info: CoreCommandRouter::Close All Modals sent 2019-12-14T17:06:30.892Z - info: CoreStateMachine::resetVolumioState 2019-12-14T17:06:30.894Z - info: CoreStateMachine::getcurrentVolume 2019-12-14T17:06:30.895Z - info: CoreCommandRouter::volumioRetrievevolume 2019-12-14T17:06:30.908Z - info: CoreStateMachine::pushState 2019-12-14T17:06:30.912Z - info: CoreStateMachine::getState 2019-12-14T17:06:30.913Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:06:30.915Z - info: CoreCommandRouter::volumioPushState 2019-12-14T17:06:30.916Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T17:06:31.576Z - info: Volumio called home 2019-12-14T17:06:31.584Z - info: Setting Device type: Raspberry PI 2019-12-14T17:06:31.595Z - info: MPD running with PID719 ,establishing connection 2019-12-14T17:06:31.857Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable 2019-12-14T17:06:31.945Z - info: CoreCommandRouter::executeOnPlugin: raat , onStop 2019-12-14T17:06:31.948Z - info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect 2019-12-14T17:06:32.100Z - info: Reloading queue from file 2019-12-14T17:06:32.273Z - info: CoreStateMachine::setRepeat false single undefined 2019-12-14T17:06:32.274Z - info: CoreStateMachine::pushState 2019-12-14T17:06:32.275Z - info: CoreStateMachine::getState 2019-12-14T17:06:32.276Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:06:32.277Z - info: CoreCommandRouter::volumioPushState 2019-12-14T17:06:32.278Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T17:06:32.286Z - info: CoreStateMachine::setRandom false 2019-12-14T17:06:32.286Z - info: CoreStateMachine::pushState 2019-12-14T17:06:32.287Z - info: CoreStateMachine::getState 2019-12-14T17:06:32.288Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:06:32.289Z - info: CoreCommandRouter::volumioPushState 2019-12-14T17:06:32.290Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T17:06:32.343Z - info: CoreCommandRouter::volumioGetState 2019-12-14T17:06:32.344Z - info: CoreStateMachine::getState 2019-12-14T17:06:32.345Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:06:32.498Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom 2019-12-14T17:06:32.506Z - info: Listing playlists 2019-12-14T17:06:32.508Z - info: CoreCommandRouter::volumioGetQueue 2019-12-14T17:06:32.509Z - info: CoreStateMachine::getQueue 2019-12-14T17:06:32.511Z - info: CorePlayQueue::getQueue 2019-12-14T17:06:32.513Z - info: CoreCommandRouter::volumioGetVisibleSources 2019-12-14T17:06:32.514Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:33.045Z - info: [LastFM] using existing timer 2019-12-14T17:06:33.047Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: mpd | duration: 332 | title: The Song Remains The Same | previous title: The Song Remains The Same | Initializing: true 2019-12-14T17:06:33.047Z - info: =================> [timer] is active: false | can continue: false | timer started at: undefined 2019-12-14T17:06:33.050Z - info: [LastFM] stopping timer, song has ended. 2019-12-14T17:06:33.059Z - info: [LastFM] using existing timer 2019-12-14T17:06:33.060Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: mpd | duration: 332 | title: The Song Remains The Same | previous title: The Song Remains The Same 2019-12-14T17:06:33.061Z - info: =================> [timer] is active: false | can continue: false | timer started at: undefined 2019-12-14T17:06:33.062Z - info: [LastFM] stopping timer, song has ended. 2019-12-14T17:06:33.097Z - info: mDNS: Found device Volumio 2019-12-14T17:06:33.185Z - info: Shairport-Sync Started 2019-12-14T17:06:33.193Z - info: Shairport-Sync Started 2019-12-14T17:06:33.243Z - info: mDNS: Found device Volumio 2019-12-14T17:06:37.339Z - info: CoreCommandRouter::volumioGetState 2019-12-14T17:06:37.340Z - info: CoreStateMachine::getState 2019-12-14T17:06:37.341Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:06:38.307Z - info: Upmpdcli Daemon Started 2019-12-14T17:06:45.455Z - info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar 2019-12-14T17:06:45.459Z - info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar 2019-12-14T17:06:45.461Z - info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar 2019-12-14T17:06:45.463Z - info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar 2019-12-14T17:06:45.466Z - info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso 2019-12-14T17:06:45.469Z - info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso 2019-12-14T17:06:45.476Z - info: Adding plugin bluetooth to MyMusic Plugins 2019-12-14T17:06:45.479Z - info: Adding plugin cd_controller to MyMusic Plugins 2019-12-14T17:06:45.486Z - info: Adding plugin smart_inputs to MyMusic Plugins 2019-12-14T17:06:45.493Z - info: [MyVolumio PluginManager] Loading plugin "my_volumio"... 2019-12-14T17:06:49.547Z - info: [MyVolumio PluginManager] Loading plugin "streaming_services"... 2019-12-14T17:06:51.781Z - info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded 2019-12-14T17:06:51.785Z - info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio 2019-12-14T17:06:51.789Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:51.790Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:51.794Z - info: Starting MyVolumio Remote Streaming Endpoints 2019-12-14T17:06:51.845Z - info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded 2019-12-14T17:06:51.847Z - info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services 2019-12-14T17:06:51.850Z - info: Streaming services startup 2019-12-14T17:06:51.857Z - info: Starting Streaming Daemon 2019-12-14T17:06:51.919Z - info: [MyVolumio PluginManager] MyVolumio plugin successfully started 2019-12-14T17:06:53.169Z - info: MYVOLUMIO SUCCESSFULLY LOGGED IN 2019-12-14T17:06:53.171Z - info: MYVOLUMIO: Adding device 2019-12-14T17:06:53.172Z - info: MYVOLUMIO: Evaluating Server 2019-12-14T17:06:54.892Z - info: [MyVolumio PluginManager] Subscribed plan changed to virtuoso 2019-12-14T17:06:54.896Z - info: Removing browser output: myVolumio user plan is not superstar 2019-12-14T17:06:54.898Z - info: Removing audio output: 2019-12-14T17:06:54.924Z - info: Remote config written successfully 2019-12-14T17:06:54.927Z - info: Starting Tunnel 1 2019-12-14T17:06:54.932Z - info: Starting Tunnel Connection Checker 2019-12-14T17:06:55.024Z - info: Setting Geolocation for MyVolumio to eu1 2019-12-14T17:06:55.027Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:55.028Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:55.029Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:55.063Z - info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... 2019-12-14T17:06:55.074Z - info: MyVolumio status changed 2019-12-14T17:06:55.076Z - info: Streaming services startup 2019-12-14T17:06:55.081Z - info: Re-Starting Streaming Daemon 2019-12-14T17:06:55.186Z - info: Remote SSH Started 2019-12-14T17:06:55.503Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid 2019-12-14T17:06:55.516Z - info: [MyVolumio PluginManager] Loading plugin "bluetooth"... 2019-12-14T17:06:55.971Z - info: [1576343215970] Starting BluetoothController 2019-12-14T17:06:56.145Z - info: [MyVolumio PluginManager] Loading plugin "cd_controller"... 2019-12-14T17:06:56.209Z - info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth 2019-12-14T17:06:56.211Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-14T17:06:56.247Z - info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller 2019-12-14T17:06:56.256Z - info: Adding CD REST API Endpoints 2019-12-14T17:06:56.258Z - info: Adding detectCD REST Endpoint for plugin: music_service/cd_controller 2019-12-14T17:06:56.259Z - info: Adding cdRemove REST Endpoint for plugin: music_service/cd_controller 2019-12-14T17:06:56.260Z - info: Adding cdPostScan REST Endpoint for plugin: music_service/cd_controller 2019-12-14T17:06:56.261Z - info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller 2019-12-14T17:06:56.262Z - info: Detecting CD presence 2019-12-14T17:06:56.284Z - info: Updating MyVolumio device info 2019-12-14T17:06:56.285Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:56.286Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:56.287Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:06:56.451Z - info: Bluetooth name changed to Volumio 2019-12-14T17:06:56.476Z - info: Fetching Streaming Services browse cache 2019-12-14T17:06:56.571Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesQOBUZ 2019-12-14T17:06:56.573Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:56.594Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T17:06:56.595Z - info: [1576343216595] CoreMusicLibrary::Adding element TIDAL 2019-12-14T17:06:56.596Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:56.826Z - info: CoreCommandRouter::volumioGetState 2019-12-14T17:06:56.827Z - info: CoreStateMachine::getState 2019-12-14T17:06:56.828Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:06:57.985Z - info: Fetching Streaming Services browse cache 2019-12-14T17:06:58.194Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-14T17:06:58.197Z - info: [1576343218194] CoreMusicLibrary::Adding element TIDAL 2019-12-14T17:06:58.197Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:58.219Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesQOBUZ 2019-12-14T17:06:58.220Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-14T17:06:59.455Z - info: Volumio BT Module successfully started 2019-12-14T17:07:00.484Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion 2019-12-14T17:07:00.494Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-14T17:07:34.883Z - info: ---------------------------- MPD announces system playlist update 2019-12-14T17:07:34.885Z - info: Ignoring MPD Status Update 2019-12-14T17:07:34.886Z - info: ---------------------------- MPD announces state update: player 2019-12-14T17:07:34.889Z - info: ControllerMpd::getState 2019-12-14T17:07:34.891Z - info: ControllerMpd::sendMpdCommand status 2019-12-14T17:07:34.893Z - info: sending command... 2019-12-14T17:07:34.897Z - info: 2019-12-14T17:07:34.900Z - info: ------------------------------ 19ms 2019-12-14T17:07:34.902Z - info: parsing response... 2019-12-14T17:07:34.909Z - info: ControllerMpd::parseState 2019-12-14T17:07:34.911Z - info: ControllerMpd::pushState 2019-12-14T17:07:34.913Z - info: CoreCommandRouter::servicePushState 2019-12-14T17:07:34.920Z - info: CoreStateMachine::syncState 2019-12-14T17:07:34.921Z - info: CoreStateMachine::pushState 2019-12-14T17:07:34.922Z - info: CoreStateMachine::getState 2019-12-14T17:07:34.922Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:07:34.923Z - info: CoreCommandRouter::volumioPushState 2019-12-14T17:07:34.923Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T17:07:34.971Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:07:34.973Z - info: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} 2019-12-14T17:07:34.973Z - info: CURRENT POSITION 0 2019-12-14T17:07:34.974Z - info: CoreStateMachine::syncState stateService stop 2019-12-14T17:07:34.975Z - info: CoreStateMachine::syncState currentStatus stop 2019-12-14T17:07:34.976Z - info: CoreStateMachine::pushState 2019-12-14T17:07:34.976Z - info: CoreStateMachine::getState 2019-12-14T17:07:34.977Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:07:34.978Z - info: CoreCommandRouter::volumioPushState 2019-12-14T17:07:34.979Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T17:07:35.032Z - info: No code 2019-12-14T17:07:35.033Z - info: CoreStateMachine::pushState 2019-12-14T17:07:35.034Z - info: CoreStateMachine::getState 2019-12-14T17:07:35.035Z - info: CorePlayQueue::getTrack 0 2019-12-14T17:07:35.035Z - info: CoreCommandRouter::volumioPushState 2019-12-14T17:07:35.036Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-14T17:07:35.111Z - info: ------------------------------ 225ms 2019-12-14T17:07:35.126Z - info: [LastFM] using existing timer 2019-12-14T17:07:35.127Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: mpd | duration: 332 | title: The Song Remains The Same | previous title: The Song Remains The Same 2019-12-14T17:07:35.128Z - info: =================> [timer] is active: false | can continue: false | timer started at: undefined 2019-12-14T17:07:35.129Z - info: [LastFM] stopping timer, song has ended. 2019-12-14T17:07:35.133Z - info: [LastFM] using existing timer 2019-12-14T17:07:35.134Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: mpd | duration: 332 | title: The Song Remains The Same | previous title: The Song Remains The Same 2019-12-14T17:07:35.135Z - info: =================> [timer] is active: false | can continue: false | timer started at: undefined 2019-12-14T17:07:35.136Z - info: [LastFM] stopping timer, song has ended. 2019-12-14T17:07:35.139Z - info: [LastFM] using existing timer 2019-12-14T17:07:35.140Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: mpd | duration: 332 | title: The Song Remains The Same | previous title: The Song Remains The Same 2019-12-14T17:07:35.141Z - info: =================> [timer] is active: false | can continue: false | timer started at: undefined 2019-12-14T17:07:35.142Z - info: [LastFM] stopping timer, song has ended.

tomstephens89 · December 15, 2019, 12:17pm

I have just stumbled across this which smells very similar. I am applying the fix from mich_p thats in that thread. Is it possible it has not been included in the latest builds and the lastfm plugin causes these timing issues?

play-stops-midway-through-queue-since-444-t11180-10.html

EDIT:

Fix made no difference. Exactly the same behaviour. Song finishes and Volumio seemingly runs through its startup procedure.

2019-12-15T12:23:48.816Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T12:23:48.865Z - info: CoreStateMachine::pushState 2019-12-15T12:23:48.866Z - info: CoreStateMachine::getState 2019-12-15T12:23:48.867Z - info: CorePlayQueue::getTrack 0 2019-12-15T12:23:48.868Z - info: CoreCommandRouter::volumioPushState 2019-12-15T12:23:48.868Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T12:23:48.928Z - info: ------------------------------ 240ms 2019-12-15T12:23:49.907Z - info: [LastFM] corrected track title from: The Song Remains The Same to: The Song Remains the Same 2019-12-15T12:24:50.449Z - info: Tunnel connection is inactive, restarting it 2019-12-15T12:24:50.452Z - info: Starting Tunnel 1 2019-12-15T12:24:50.455Z - info: Starting Tunnel Connection Checker 2019-12-15T12:24:50.659Z - info: Remote SSH Started 2019-12-15T12:24:50.757Z - info: CoreCommandRouter::volumioGetState 2019-12-15T12:24:50.759Z - info: CoreStateMachine::getState 2019-12-15T12:24:50.760Z - info: CorePlayQueue::getTrack 0 2019-12-15T12:27:50.466Z - info: Tunnel connection is inactive, restarting it 2019-12-15T12:27:50.467Z - info: Starting Tunnel 1 2019-12-15T12:27:50.468Z - info: Starting Tunnel Connection Checker 2019-12-15T12:27:50.667Z - info: Remote SSH Started 2019-12-15T12:27:50.747Z - info: CoreCommandRouter::volumioGetState 2019-12-15T12:27:50.748Z - info: CoreStateMachine::getState 2019-12-15T12:27:50.748Z - info: CorePlayQueue::getTrack 0 2019-12-15T12:28:04.276Z - info: ------------------------------------------- 2019-12-15T12:28:04.282Z - info: ----- Volumio2 ---- 2019-12-15T12:28:04.283Z - info: ------------------------------------------- 2019-12-15T12:28:04.283Z - info: ----- System startup ---- 2019-12-15T12:28:04.284Z - info: ------------------------------------------- 2019-12-15T12:28:04.446Z - info: MYVOLUMIO Environment detected 2019-12-15T12:28:05.780Z - info: Plugin folders cleanup 2019-12-15T12:28:05.781Z - info: Scanning into folder /volumio/app/plugins/

tomstephens89 · December 15, 2019, 1:13pm

More logs:

logs.volumio.org/volumio/GwVeKi9.html

tomstephens89 · December 15, 2019, 1:38pm

And heres a log with an interesting error. Played 2 tracks from the queue, then problem occurred into the second track and player went into stopped state so 3rd track didn’t play.

Note this error:

2019-12-15T13:34:11.982Z - info: ERROR Prefetch 500ms setTimeout missed >> directly calling increasePlaybackTimer 2019-12-15T13:34:11.982Z - info: ERROR this.runPlaybackTimer:true this.currentSongDuration:281000 - this.currentSeek:276118 - this.prefetchDone:true - this.simulateStopStartDone:false 2019-12-15T13:34:11.982Z - info: ERROR increasePlaybackTimer remainingTime:-20 negative - askedForPrefetch:true - simulateStopStartDone:false

2019-12-15T13:29:34.489Z - info: CURURI: artists://AC%2FDC/'74%20Jailbreak 2019-12-15T13:29:36.267Z - info: CoreCommandRouter::volumioAddQueueItems 2019-12-15T13:29:36.268Z - info: CoreStateMachine::addQueueItems 2019-12-15T13:29:36.269Z - info: CorePlayQueue::addQueueItems 2019-12-15T13:29:36.270Z - info: Adding Item to queue: artists://AC%2FDC/'74%20Jailbreak 2019-12-15T13:29:36.271Z - info: Exploding uri artists://AC%2FDC/'74%20Jailbreak in service mpd 2019-12-15T13:29:36.285Z - info: CorePlayQueue::saveQueue 2019-12-15T13:29:36.286Z - info: CoreCommandRouter::volumioPushQueue 2019-12-15T13:29:36.291Z - info: CoreStateMachine::updateTrackBlock 2019-12-15T13:29:36.292Z - info: CorePlayQueue::getTrackBlock 2019-12-15T13:29:36.293Z - info: CoreCommandRouter::volumioPlay 2019-12-15T13:29:36.295Z - info: CoreStateMachine::play index 0 2019-12-15T13:29:36.295Z - info: CoreStateMachine::setConsumeUpdateService undefined 2019-12-15T13:29:36.297Z - info: CoreStateMachine::stop 2019-12-15T13:29:36.297Z - info: CoreStateMachine::setConsumeUpdateService undefined 2019-12-15T13:29:36.298Z - info: CoreStateMachine::play index undefined 2019-12-15T13:29:36.298Z - info: CoreStateMachine::setConsumeUpdateService undefined 2019-12-15T13:29:36.299Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:29:36.300Z - info: CoreStateMachine::startPlaybackTimer 2019-12-15T13:29:36.300Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:29:36.302Z - info: ControllerMpd::clearAddPlayTracks USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/01. AC-DC - Jailbreak (Album Version).flac 2019-12-15T13:29:36.302Z - info: ControllerMpd::sendMpdCommand stop 2019-12-15T13:29:36.305Z - info: sending command... 2019-12-15T13:29:36.307Z - info: parsing response... 2019-12-15T13:29:36.307Z - info: ControllerMpd::sendMpdCommand clear 2019-12-15T13:29:36.308Z - info: sending command... 2019-12-15T13:29:36.311Z - info: ---------------------------- MPD announces system playlist update 2019-12-15T13:29:36.311Z - info: Ignoring MPD Status Update 2019-12-15T13:29:36.312Z - info: parsing response... 2019-12-15T13:29:36.313Z - info: ControllerMpd::sendMpdCommand add "USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/01. AC-DC - Jailbreak (Album Version).flac" 2019-12-15T13:29:36.314Z - info: sending command... 2019-12-15T13:29:36.319Z - info: 2019-12-15T13:29:36.320Z - info: ---------------------------- MPD announces system playlist update 2019-12-15T13:29:36.320Z - info: Ignoring MPD Status Update 2019-12-15T13:29:36.321Z - info: ------------------------------ 11ms 2019-12-15T13:29:36.321Z - info: parsing response... 2019-12-15T13:29:36.322Z - info: ControllerMpd::sendMpdCommand play 2019-12-15T13:29:36.323Z - info: sending command... 2019-12-15T13:29:36.328Z - info: ------------------------------ 9ms 2019-12-15T13:29:36.329Z - info: parsing response... 2019-12-15T13:29:36.356Z - info: ---------------------------- MPD announces state update: player 2019-12-15T13:29:36.357Z - info: ControllerMpd::getState 2019-12-15T13:29:36.358Z - info: ControllerMpd::sendMpdCommand status 2019-12-15T13:29:36.359Z - info: sending command... 2019-12-15T13:29:36.360Z - info: ---------------------------- MPD announces state update: player 2019-12-15T13:29:36.361Z - info: ControllerMpd::getState 2019-12-15T13:29:36.362Z - info: ControllerMpd::sendMpdCommand status 2019-12-15T13:29:36.363Z - info: parsing response... 2019-12-15T13:29:36.364Z - info: sending command... 2019-12-15T13:29:36.365Z - info: ControllerMpd::parseState 2019-12-15T13:29:36.367Z - info: ControllerMpd::sendMpdCommand playlistinfo 2019-12-15T13:29:36.367Z - info: sending command... 2019-12-15T13:29:36.369Z - info: parsing response... 2019-12-15T13:29:36.370Z - info: parsing response... 2019-12-15T13:29:36.371Z - info: ControllerMpd::parseState 2019-12-15T13:29:36.372Z - info: ControllerMpd::sendMpdCommand playlistinfo 2019-12-15T13:29:36.374Z - info: ControllerMpd::parseTrackInfo 2019-12-15T13:29:36.375Z - info: sending command... 2019-12-15T13:29:36.376Z - info: ControllerMpd::pushState 2019-12-15T13:29:36.377Z - info: CoreCommandRouter::servicePushState 2019-12-15T13:29:36.377Z - info: CoreStateMachine::syncState 2019-12-15T13:29:36.378Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:29:36.378Z - info: STATE SERVICE {"status":"play","position":0,"seek":464,"duration":281,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStrea ming":false,"title":"Jailbreak (Album Version)","artist":"AC/DC","album":"'74 Jailbreak","uri":"USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/01. AC-DC - Jailbreak (Album Version).flac","trackType":"flac"} 2019-12-15T13:29:36.379Z - info: CURRENT POSITION 0 2019-12-15T13:29:36.379Z - info: CoreStateMachine::syncState stateService play 2019-12-15T13:29:36.380Z - info: CoreStateMachine::syncState currentStatus stop 2019-12-15T13:29:36.380Z - info: CoreStateMachine::pushState 2019-12-15T13:29:36.380Z - info: CoreStateMachine::getState 2019-12-15T13:29:36.381Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:29:36.381Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:29:36.382Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:29:36.413Z - info: ------------------------------ 57ms 2019-12-15T13:29:36.416Z - info: parsing response... 2019-12-15T13:29:36.419Z - info: ControllerMpd::parseTrackInfo 2019-12-15T13:29:36.420Z - info: ControllerMpd::pushState 2019-12-15T13:29:36.421Z - info: CoreCommandRouter::servicePushState 2019-12-15T13:29:36.422Z - info: CoreStateMachine::syncState 2019-12-15T13:29:36.423Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:29:36.423Z - info: STATE SERVICE {"status":"play","position":0,"seek":464,"duration":281,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStrea ming":false,"title":"Jailbreak (Album Version)","artist":"AC/DC","album":"'74 Jailbreak","uri":"USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/01. AC-DC - Jailbreak (Album Version).flac","trackType":"flac"} 2019-12-15T13:29:36.424Z - info: CURRENT POSITION 0 2019-12-15T13:29:36.424Z - info: CoreStateMachine::syncState stateService play 2019-12-15T13:29:36.425Z - info: CoreStateMachine::syncState currentStatus play 2019-12-15T13:29:36.426Z - info: Received an update from plugin. extracting info from payload 2019-12-15T13:29:36.427Z - info: CoreStateMachine::pushState 2019-12-15T13:29:36.427Z - info: CoreStateMachine::getState 2019-12-15T13:29:36.428Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:29:36.428Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:29:36.430Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:29:36.452Z - info: CoreStateMachine::pushState 2019-12-15T13:29:36.452Z - info: CoreStateMachine::getState 2019-12-15T13:29:36.453Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:29:36.453Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:29:36.454Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:29:36.492Z - info: ------------------------------ 132ms 2019-12-15T13:29:36.501Z - info: [LastFM] using existing timer 2019-12-15T13:29:36.502Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: mpd | duration: 281 | title: Jailbreak (Album Versi on) | previous title: 2019-12-15T13:29:36.502Z - info: =================> [timer] is active: false | can continue: false | timer started at: undefined 2019-12-15T13:29:36.503Z - info: Playback detected, evaluating parameters for scrobbling... 2019-12-15T13:29:36.504Z - info: [LastFM] Updating now playing 2019-12-15T13:29:36.508Z - info: [LastFM] trying to authenticate... 2019-12-15T13:29:36.514Z - info: [LastFM] Continuing playback or different song. 2019-12-15T13:29:36.514Z - info: [LastFM] timeToPlay for current track: 0 2019-12-15T13:29:36.515Z - info: [LastFM] starting new timer for 210750 milliseconds [AC/DC - Jailbreak (Album Version)]. 2019-12-15T13:29:36.519Z - info: [LastFM] using existing timer 2019-12-15T13:29:36.520Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: mpd | duration: 281 | title: Jailbreak (Album Versi on) | previous title: Jailbreak (Album Version) 2019-12-15T13:29:36.521Z - info: =================> [timer] is active: true | can continue: false | timer started at: 1576416576517 2019-12-15T13:29:36.522Z - info: Playback detected, evaluating parameters for scrobbling... 2019-12-15T13:29:36.522Z - info: [LastFM] Updating now playing 2019-12-15T13:29:36.523Z - info: [LastFM] trying to authenticate... 2019-12-15T13:29:36.527Z - info: [LastFM] same state, different update... no action required. 2019-12-15T13:29:36.529Z - info: [LastFM] using existing timer 2019-12-15T13:29:36.529Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: mpd | duration: 281 | title: Jailbreak (Album Versi on) | previous title: Jailbreak (Album Version) 2019-12-15T13:29:36.530Z - info: =================> [timer] is active: true | can continue: false | timer started at: 1576416576517 2019-12-15T13:29:36.530Z - info: Playback detected, evaluating parameters for scrobbling... 2019-12-15T13:29:36.530Z - info: [LastFM] Updating now playing 2019-12-15T13:29:36.530Z - info: [LastFM] trying to authenticate... 2019-12-15T13:29:36.532Z - info: [LastFM] same state, different update... no action required. 2019-12-15T13:29:36.923Z - info: [LastFM] authenticated successfully! 2019-12-15T13:29:36.937Z - info: [LastFM] authenticated successfully! 2019-12-15T13:29:36.944Z - info: [LastFM] authenticated successfully! 2019-12-15T13:29:37.231Z - info: [LastFM] updated "now playing" | artist: AC/DC | title: Jailbreak (Album Version) 2019-12-15T13:29:37.238Z - info: [LastFM] updated "now playing" | artist: AC/DC | title: Jailbreak (Album Version) 2019-12-15T13:29:37.251Z - info: [LastFM] updated "now playing" | artist: AC/DC | title: Jailbreak (Album Version) 2019-12-15T13:33:06.219Z - info: Tunnel connection is inactive, restarting it 2019-12-15T13:33:06.221Z - info: Starting Tunnel 1 2019-12-15T13:33:06.223Z - info: Starting Tunnel Connection Checker 2019-12-15T13:33:06.331Z - info: Remote SSH Started 2019-12-15T13:33:06.389Z - info: CoreCommandRouter::volumioGetState 2019-12-15T13:33:06.390Z - info: CoreStateMachine::getState 2019-12-15T13:33:06.391Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:33:07.269Z - info: [LastFM] scrobbling from restarted timer. 2019-12-15T13:33:07.272Z - info: [LastFM] checking previously scrobbled song... 2019-12-15T13:33:07.273Z - info: [LastFM] previous scrobble: {"artist":"","title":"","scrobbleTime":0} 2019-12-15T13:33:07.275Z - info: [LastFM] trying to authenticate for scrobbling... 2019-12-15T13:33:07.686Z - info: [LastFM] authenticated successfully for scrobbling! 2019-12-15T13:33:07.688Z - info: [LastFM] preparing to scrobble... 2019-12-15T13:33:07.990Z - info: [LastFM] Scrobble successful for: AC/DC - Jailbreak (Album Version) ('74 Jailbreak). 2019-12-15T13:34:11.962Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:34:11.964Z - info: CorePlayQueue::getTrack 1 2019-12-15T13:34:11.964Z - info: Prefetching next song 2019-12-15T13:34:11.965Z - info: DOING PREFETCH IN MPD 2019-12-15T13:34:11.966Z - info: ControllerMpd::sendMpdCommand add "USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/02. AC-DC - You Ain't Got A Hold On Me (Album Version).flac" 2019-12-15T13:34:11.966Z - info: sending command... 2019-12-15T13:34:11.968Z - info: ---------------------------- MPD announces system playlist update 2019-12-15T13:34:11.969Z - info: Ignoring MPD Status Update 2019-12-15T13:34:11.970Z - info: parsing response... 2019-12-15T13:34:11.971Z - info: ControllerMpd::sendMpdCommand consume 1 2019-12-15T13:34:11.972Z - info: sending command... 2019-12-15T13:34:11.974Z - info: ---------------------------- MPD announces state update: options 2019-12-15T13:34:11.975Z - info: ------------------------------ 6ms 2019-12-15T13:34:11.975Z - info: parsing response... 2019-12-15T13:34:11.975Z - info: ControllerMpd::getState 2019-12-15T13:34:11.975Z - info: ControllerMpd::sendMpdCommand status 2019-12-15T13:34:11.976Z - info: sending command... 2019-12-15T13:34:11.977Z - info: parsing response... 2019-12-15T13:34:11.978Z - info: ControllerMpd::parseState 2019-12-15T13:34:11.978Z - info: ControllerMpd::sendMpdCommand playlistinfo 2019-12-15T13:34:11.979Z - info: sending command... 2019-12-15T13:34:11.980Z - info: parsing response... 2019-12-15T13:34:11.980Z - info: ControllerMpd::parseTrackInfo 2019-12-15T13:34:11.981Z - info: ControllerMpd::pushState 2019-12-15T13:34:11.981Z - info: CoreCommandRouter::servicePushState 2019-12-15T13:34:11.981Z - info: CoreStateMachine::syncState 2019-12-15T13:34:11.982Z - info: ERROR Prefetch 500ms setTimeout missed >> directly calling increasePlaybackTimer 2019-12-15T13:34:11.982Z - info: ERROR this.runPlaybackTimer:true this.currentSongDuration:281000 - this.currentSeek:276118 - this.prefetchDone:true - this.simulateStopStartDone:false 2019-12-15T13:34:11.982Z - info: ERROR increasePlaybackTimer remainingTime:-20 negative - askedForPrefetch:true - simulateStopStartDone:false 2019-12-15T13:34:11.982Z - info: CoreStateMachine::startPlaybackTimer 2019-12-15T13:34:11.983Z - info: CorePlayQueue::getTrack 1 2019-12-15T13:34:11.983Z - info: CorePlayQueue::getTrack 1 2019-12-15T13:34:11.991Z - info: STATE SERVICE {"status":"play","position":0,"seek":276062,"duration":281,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"Jailbreak (Album Version)","artist":"AC/DC","album":"'74 Jailbreak","uri":"USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/01. AC-DC - Jailbreak (Album Version).flac","trackType":"flac"} 2019-12-15T13:34:11.992Z - info: CURRENT POSITION 1 2019-12-15T13:34:11.992Z - info: CoreStateMachine::syncState stateService play 2019-12-15T13:34:11.993Z - info: CoreStateMachine::syncState currentStatus play 2019-12-15T13:34:11.993Z - info: Received an update from plugin. extracting info from payload 2019-12-15T13:34:11.994Z - info: CoreStateMachine::pushState 2019-12-15T13:34:11.995Z - info: CoreStateMachine::getState 2019-12-15T13:34:11.996Z - info: CorePlayQueue::getTrack 1 2019-12-15T13:34:11.996Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:34:11.997Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:34:12.020Z - info: CoreStateMachine::pushState 2019-12-15T13:34:12.020Z - info: CoreStateMachine::getState 2019-12-15T13:34:12.021Z - info: CorePlayQueue::getTrack 1 2019-12-15T13:34:12.022Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:34:12.022Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:34:12.054Z - info: ------------------------------ 79ms 2019-12-15T13:34:12.061Z - info: [LastFM] using existing timer 2019-12-15T13:34:12.062Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: mpd | duration: 281 | title: You Ain't Got A Hold On Me (Album Version) | previous title: Jailbreak (Album Version) 2019-12-15T13:34:12.063Z - info: =================> [timer] is active: false | can continue: false | timer started at: 1576416576517 2019-12-15T13:34:12.064Z - info: Playback detected, evaluating parameters for scrobbling... 2019-12-15T13:34:12.064Z - info: [LastFM] Updating now playing 2019-12-15T13:34:12.065Z - info: [LastFM] trying to authenticate... 2019-12-15T13:34:12.067Z - info: [LastFM] Continuing playback or different song. 2019-12-15T13:34:12.068Z - info: [LastFM] timeToPlay for current track: 0 2019-12-15T13:34:12.068Z - info: [LastFM] starting new timer for 210750 milliseconds [AC/DC - You Ain't Got A Hold On Me (Album Version)]. 2019-12-15T13:34:12.071Z - info: [LastFM] using existing timer 2019-12-15T13:34:12.071Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: mpd | duration: 281 | title: You Ain't Got A Hold On Me (Album Version) | previous title: You Ain't Got A Hold On Me (Album Version) 2019-12-15T13:34:12.072Z - info: =================> [timer] is active: true | can continue: false | timer started at: 1576416852068 2019-12-15T13:34:12.072Z - info: Playback detected, evaluating parameters for scrobbling... 2019-12-15T13:34:12.073Z - info: [LastFM] Updating now playing 2019-12-15T13:34:12.073Z - info: [LastFM] trying to authenticate... 2019-12-15T13:34:12.075Z - info: [LastFM] same state, different update... no action required. 2019-12-15T13:34:12.216Z - info: ERROR increasePlaybackTimer remainingTime:-65295 negative - askedForPrefetch:false - simulateStopStartDone:false 2019-12-15T13:34:12.217Z - info: CorePlayQueue::getTrack 1 2019-12-15T13:34:12.217Z - info: CorePlayQueue::getTrack 2 2019-12-15T13:34:12.218Z - info: Prefetching next song 2019-12-15T13:34:12.218Z - info: DOING PREFETCH IN MPD 2019-12-15T13:34:12.218Z - info: ControllerMpd::sendMpdCommand add "USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/03. AC-DC - Show Business (Album Version).flac" 2019-12-15T13:34:12.219Z - info: CoreStateMachine::startPlaybackTimer 2019-12-15T13:34:12.219Z - info: CorePlayQueue::getTrack 2 2019-12-15T13:34:12.219Z - info: sending command... 2019-12-15T13:34:12.221Z - info: ---------------------------- MPD announces system playlist update 2019-12-15T13:34:12.221Z - info: Ignoring MPD Status Update 2019-12-15T13:34:12.222Z - info: parsing response... 2019-12-15T13:34:12.222Z - info: ControllerMpd::sendMpdCommand consume 1 2019-12-15T13:34:12.223Z - info: sending command... 2019-12-15T13:34:12.224Z - info: ------------------------------ 4ms 2019-12-15T13:34:12.225Z - info: parsing response... 2019-12-15T13:34:12.460Z - info: [LastFM] authenticated successfully! 2019-12-15T13:34:12.483Z - info: [LastFM] authenticated successfully! 2019-12-15T13:34:12.749Z - info: [LastFM] corrected track title from: You Ain't Got A Hold On Me (Album Version) to: You Ain't Got a Hold on Me 2019-12-15T13:34:12.765Z - info: [LastFM] updated "now playing" | artist: AC/DC | title: You Ain't Got a Hold on Me 2019-12-15T13:34:12.776Z - info: [LastFM] updated "now playing" | artist: AC/DC | title: You Ain't Got a Hold on Me 2019-12-15T13:34:16.858Z - info: ---------------------------- MPD announces system playlist update 2019-12-15T13:34:16.859Z - info: Ignoring MPD Status Update 2019-12-15T13:34:16.859Z - info: ---------------------------- MPD announces state update: player 2019-12-15T13:34:16.859Z - info: ControllerMpd::getState 2019-12-15T13:34:16.860Z - info: ControllerMpd::sendMpdCommand status 2019-12-15T13:34:16.860Z - info: sending command... 2019-12-15T13:34:16.862Z - info: ------------------------------ 5ms 2019-12-15T13:34:16.863Z - info: parsing response... 2019-12-15T13:34:16.864Z - info: ControllerMpd::parseState 2019-12-15T13:34:16.864Z - info: ControllerMpd::sendMpdCommand playlistinfo 2019-12-15T13:34:16.864Z - info: sending command... 2019-12-15T13:34:16.866Z - info: parsing response... 2019-12-15T13:34:16.867Z - info: ControllerMpd::parseTrackInfo 2019-12-15T13:34:16.867Z - info: ControllerMpd::pushState 2019-12-15T13:34:16.868Z - info: CoreCommandRouter::servicePushState 2019-12-15T13:34:16.868Z - info: CoreStateMachine::syncState 2019-12-15T13:34:16.868Z - info: CorePlayQueue::getTrack 2 2019-12-15T13:34:16.868Z - info: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":211,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"You Ain't Got A Hold On Me (Album Version)","artist":"AC/DC","album":"'74 Jailbreak","uri":"USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/02. AC-DC - You Ain't Got A Hold On Me (Album Version).flac","trackType":"flac"} 2019-12-15T13:34:16.869Z - info: CURRENT POSITION 2 2019-12-15T13:34:16.869Z - info: CoreStateMachine::syncState stateService play 2019-12-15T13:34:16.869Z - info: CoreStateMachine::syncState currentStatus play 2019-12-15T13:34:16.869Z - info: Received an update from plugin. extracting info from payload 2019-12-15T13:34:16.869Z - info: CoreStateMachine::pushState 2019-12-15T13:34:16.870Z - info: CoreStateMachine::getState 2019-12-15T13:34:16.870Z - info: CorePlayQueue::getTrack 2 2019-12-15T13:34:16.870Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:34:16.870Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:34:16.890Z - info: CoreStateMachine::pushState 2019-12-15T13:34:16.890Z - info: CoreStateMachine::getState 2019-12-15T13:34:16.891Z - info: CorePlayQueue::getTrack 2 2019-12-15T13:34:16.891Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:34:16.891Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:34:16.925Z - info: ------------------------------ 65ms 2019-12-15T13:34:16.931Z - info: [LastFM] using existing timer 2019-12-15T13:34:16.933Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: mpd | duration: 211 | title: Show Business (Album Version) | previous title: You Ain't Got A Hold On Me (Album Version) 2019-12-15T13:34:16.933Z - info: =================> [timer] is active: true | can continue: false | timer started at: 1576416852068 2019-12-15T13:34:16.934Z - info: Playback detected, evaluating parameters for scrobbling... 2019-12-15T13:34:16.934Z - info: [LastFM] Updating now playing 2019-12-15T13:34:16.934Z - info: [LastFM] trying to authenticate... 2019-12-15T13:34:16.937Z - info: [LastFM] could not process current state: {"status":"play","position":2,"title":"Show Business (Album Version)","artist":"AC/DC","album":"'74 Jailbreak","albumart":"/albumart?cacheid=58&web=AC%2FDC/'74%20Jailbreak/extralarge&path=%2Fmnt%2FUSB%2FMusic%2FFLAC_Collection%2FACDC%2F'74%20Jailbreak&metadata=false","uri":"music-library/USB/Music/FLAC_Collection/ACDC/'74 Jailbreak/03. AC-DC - Show Business (Album Version).flac","trackType":"flac","seek":0,"duration":211,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":100,"disableVolumeControl":true,"mute":false,"stream":"flac","updatedb":false,"volatile":false,"service":"mpd"} 2019-12-15T13:34:16.940Z - info: [LastFM] using existing timer 2019-12-15T13:34:16.941Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: mpd | duration: 211 | title: Show Business (Album Version) | previous title: Show Business (Album Version) 2019-12-15T13:34:16.942Z - info: =================> [timer] is active: true | can continue: false | timer started at: 1576416852068 2019-12-15T13:34:16.942Z - info: Playback detected, evaluating parameters for scrobbling... 2019-12-15T13:34:16.943Z - info: [LastFM] Updating now playing 2019-12-15T13:34:16.943Z - info: [LastFM] trying to authenticate... 2019-12-15T13:34:16.944Z - info: [LastFM] same state, different update... no action required. 2019-12-15T13:34:17.311Z - info: [LastFM] authenticated successfully! 2019-12-15T13:34:17.320Z - info: [LastFM] authenticated successfully! 2019-12-15T13:34:17.595Z - info: [LastFM] updated "now playing" | artist: AC/DC | title: Show Business (Album Version) 2019-12-15T13:34:17.601Z - info: [LastFM] updated "now playing" | artist: AC/DC | title: Show Business (Album Version) 2019-12-15T13:36:06.228Z - info: Tunnel connection is inactive, restarting it 2019-12-15T13:36:06.229Z - info: Starting Tunnel 1 2019-12-15T13:36:06.230Z - info: Starting Tunnel Connection Checker 2019-12-15T13:36:06.329Z - info: Remote SSH Started 2019-12-15T13:36:06.372Z - info: CoreCommandRouter::volumioGetState 2019-12-15T13:36:06.372Z - info: CoreStateMachine::getState 2019-12-15T13:36:06.373Z - info: CorePlayQueue::getTrack 2 2019-12-15T13:37:42.820Z - info: [LastFM] scrobbling from restarted timer. 2019-12-15T13:37:42.822Z - info: [LastFM] checking previously scrobbled song... 2019-12-15T13:37:42.824Z - info: [LastFM] previous scrobble: {"artist":"","title":"","scrobbleTime":0} 2019-12-15T13:37:42.825Z - info: [LastFM] trying to authenticate for scrobbling... 2019-12-15T13:37:43.169Z - info: [LastFM] authenticated successfully for scrobbling! 2019-12-15T13:37:43.171Z - info: [LastFM] preparing to scrobble... 2019-12-15T13:37:46.440Z - info: ------------------------------------------- 2019-12-15T13:37:46.442Z - info: ----- Volumio2 ---- 2019-12-15T13:37:46.443Z - info: ------------------------------------------- 2019-12-15T13:37:46.443Z - info: ----- System startup ---- 2019-12-15T13:37:46.443Z - info: ------------------------------------------- 2019-12-15T13:37:46.519Z - info: MYVOLUMIO Environment detected 2019-12-15T13:37:47.142Z - info: Plugin folders cleanup 2019-12-15T13:37:47.142Z - info: Scanning into folder /volumio/app/plugins/ 2019-12-15T13:37:47.143Z - info: Scanning category audio_interface 2019-12-15T13:37:47.144Z - info: Scanning category miscellanea 2019-12-15T13:37:47.145Z - info: Scanning category music_service 2019-12-15T13:37:47.146Z - info: Scanning category plugins.json 2019-12-15T13:37:47.147Z - info: Scanning category system_controller 2019-12-15T13:37:47.148Z - info: Scanning category user_interface 2019-12-15T13:37:47.149Z - info: Scanning into folder /data/plugins/ 2019-12-15T13:37:47.149Z - info: Scanning category miscellanea 2019-12-15T13:37:47.150Z - info: Plugin folders cleanup completed 2019-12-15T13:37:47.152Z - info: ------------------------------------------- 2019-12-15T13:37:47.152Z - info: ----- Core plugins startup ---- 2019-12-15T13:37:47.152Z - info: ------------------------------------------- 2019-12-15T13:37:47.153Z - info: Loading plugins from folder /volumio/app/plugins/ 2019-12-15T13:37:47.157Z - info: Adding plugin upnp to MyMusic Plugins 2019-12-15T13:37:47.159Z - info: Adding plugin airplay_emulation to MyMusic Plugins 2019-12-15T13:37:47.160Z - info: Adding plugin upnp_browser to MyMusic Plugins 2019-12-15T13:37:47.163Z - info: Loading plugins from folder /data/plugins/ 2019-12-15T13:37:47.166Z - info: Loading plugin "system"... 2019-12-15T13:37:47.188Z - info: Loading plugin "appearance"... 2019-12-15T13:37:47.889Z - info: Loading plugin "network"... 2019-12-15T13:37:48.111Z - info: Loading plugin "services"... 2019-12-15T13:37:48.114Z - info: Loading plugin "alsa_controller"... 2019-12-15T13:37:48.199Z - info: Loading plugin "wizard"... 2019-12-15T13:37:48.206Z - info: Loading plugin "volumio_command_line_client"... 2019-12-15T13:37:48.241Z - info: Loading plugin "upnp"... 2019-12-15T13:37:48.247Z - info: [1576417068246] Starting Upmpd Daemon 2019-12-15T13:37:48.249Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-15T13:37:48.252Z - info: Loading plugin "my_music"... 2019-12-15T13:37:48.258Z - info: Loading plugin "mpd"... 2019-12-15T13:37:48.574Z - info: Loading plugin "upnp_browser"... 2019-12-15T13:37:48.894Z - info: Loading plugin "networkfs"... 2019-12-15T13:37:49.010Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-15T13:37:49.011Z - info: Loading plugin "alarm-clock"... 2019-12-15T13:37:49.164Z - info: Loading plugin "airplay_emulation"... 2019-12-15T13:37:49.182Z - info: Starting Shairport Sync 2019-12-15T13:37:49.183Z - info: Loading plugin "last_100"... 2019-12-15T13:37:49.188Z - info: Loading plugin "webradio"... 2019-12-15T13:37:49.273Z - info: Loading plugin "i2s_dacs"... 2019-12-15T13:37:49.283Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:37:49.285Z - info: Loading plugin "volumiodiscovery"... 2019-12-15T13:37:49.322Z - info: Applying required configuration parameters for plugin volumiodiscovery 2019-12-15T13:37:49.354Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-15T13:37:49.355Z - info: Loading plugin "outputs"... 2019-12-15T13:37:49.361Z - info: Loading plugin "albumart"... 2019-12-15T13:37:49.384Z - info: Plugin example_plugin is not enabled 2019-12-15T13:37:49.385Z - info: Loading plugin "inputs"... 2019-12-15T13:37:49.392Z - info: Loading plugin "updater_comm"... 2019-12-15T13:37:49.546Z - info: Plugin mpdemulation is not enabled 2019-12-15T13:37:49.547Z - info: Loading plugin "rest_api"... 2019-12-15T13:37:49.581Z - info: Loading plugin "websocket"... 2019-12-15T13:37:49.608Z - info: Loading plugin "lastfm"... 2019-12-15T13:37:50.477Z - info: [LastFM] supported song services: ["mpd","airplay","volspotconnect","volspotconnect2","spop"] 2019-12-15T13:37:50.478Z - info: [LastFM] supported streaming services: ["webradio","radio_paradise","80s80s"] 2019-12-15T13:37:50.478Z - info: [LastFM] scrobbler initiated! 2019-12-15T13:37:50.479Z - info: [LastFM] extended logging: true 2019-12-15T13:37:50.479Z - info: [LastFM] try scrobble stream/radio plays: true 2019-12-15T13:37:50.485Z - info: ___________ START PLUGINS ___________ 2019-12-15T13:37:50.490Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-15T13:37:50.492Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-15T13:37:50.493Z - info: [1576417070493] CoreMusicLibrary::Adding element Media Servers 2019-12-15T13:37:50.495Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:37:50.607Z - info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 2019-12-15T13:37:50.664Z - info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 2019-12-15T13:37:50.666Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-15T13:37:50.666Z - info: [1576417070666] CoreMusicLibrary::Adding element Last_100 2019-12-15T13:37:50.667Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:37:50.670Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-15T13:37:50.671Z - info: [1576417070670] CoreMusicLibrary::Adding element Webradio 2019-12-15T13:37:50.671Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:37:50.685Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion 2019-12-15T13:37:50.694Z - info: Performing onStart action 2019-12-15T13:37:50.695Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-15T13:37:50.696Z - info: [1576417070695] CoreMusicLibrary::Adding element LastFM 2019-12-15T13:37:50.697Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:37:50.700Z - info: ------------------------------------------- 2019-12-15T13:37:50.700Z - info: ----- MyVolumio plugins startup ---- 2019-12-15T13:37:50.701Z - info: ------------------------------------------- 2019-12-15T13:37:50.702Z - info: [MyVolumio PluginManager] Fetching plans data.... 2019-12-15T13:37:50.708Z - info: Loading i18n strings for locale en 2019-12-15T13:37:50.716Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:37:50.735Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-15T13:37:50.738Z - info: CoreCommandRouter::initPlayerControls 2019-12-15T13:37:50.748Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-15T13:37:50.749Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getAlsaCards 2019-12-15T13:37:50.802Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-15T13:37:50.802Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-15T13:37:50.803Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-15T13:37:50.804Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-15T13:37:50.804Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam 2019-12-15T13:37:50.815Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam 2019-12-15T13:37:50.819Z - info: BOOT COMPLETED 2019-12-15T13:37:50.820Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:37:50.872Z - info: CoreCommandRouter::Close All Modals sent 2019-12-15T13:37:50.873Z - info: CoreCommandRouter::Close All Modals sent 2019-12-15T13:37:50.982Z - info: CoreStateMachine::resetVolumioState 2019-12-15T13:37:50.983Z - info: CoreStateMachine::getcurrentVolume 2019-12-15T13:37:50.984Z - info: CoreCommandRouter::volumioRetrievevolume 2019-12-15T13:37:50.995Z - info: CoreStateMachine::pushState 2019-12-15T13:37:50.997Z - info: CoreStateMachine::getState 2019-12-15T13:37:50.998Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:37:51.000Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:37:51.001Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:37:51.150Z - info: Setting Device type: Raspberry PI 2019-12-15T13:37:51.156Z - info: MPD running with PID697 ,establishing connection 2019-12-15T13:37:51.437Z - info: Volumio called home 2019-12-15T13:37:51.480Z - info: Reloading queue from file 2019-12-15T13:37:51.553Z - info: CoreStateMachine::setRepeat false single undefined 2019-12-15T13:37:51.554Z - info: CoreStateMachine::pushState 2019-12-15T13:37:51.556Z - info: CoreStateMachine::getState 2019-12-15T13:37:51.557Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:37:51.559Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:37:51.560Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:37:51.566Z - info: CoreStateMachine::setRandom false 2019-12-15T13:37:51.567Z - info: CoreStateMachine::pushState 2019-12-15T13:37:51.568Z - info: CoreStateMachine::getState 2019-12-15T13:37:51.569Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:37:51.571Z - info: CoreCommandRouter::volumioPushState 2019-12-15T13:37:51.572Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo 2019-12-15T13:37:51.806Z - info: [LastFM] using existing timer 2019-12-15T13:37:51.808Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: mpd | duration: 281 | title: Jailbreak (Album Version) | previous title: Jailbreak (Album Version) | Initializing: true 2019-12-15T13:37:51.808Z - info: =================> [timer] is active: false | can continue: false | timer started at: undefined 2019-12-15T13:37:51.810Z - info: [LastFM] stopping timer, song has ended. 2019-12-15T13:37:51.814Z - info: [LastFM] using existing timer 2019-12-15T13:37:51.814Z - info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: stop | service: mpd | duration: 281 | title: Jailbreak (Album Version) | previous title: Jailbreak (Album Version) 2019-12-15T13:37:51.815Z - info: =================> [timer] is active: false | can continue: false | timer started at: undefined 2019-12-15T13:37:51.816Z - info: [LastFM] stopping timer, song has ended. 2019-12-15T13:37:51.830Z - info: mDNS: Found device Volumio 2019-12-15T13:37:51.927Z - info: Shairport-Sync Started 2019-12-15T13:37:51.931Z - info: Shairport-Sync Started 2019-12-15T13:37:51.932Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable 2019-12-15T13:37:51.975Z - info: CoreCommandRouter::executeOnPlugin: raat , onStop 2019-12-15T13:37:51.975Z - info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect 2019-12-15T13:37:51.987Z - info: mDNS: Found device Volumio 2019-12-15T13:37:52.085Z - info: CoreCommandRouter::volumioGetState 2019-12-15T13:37:52.086Z - info: CoreStateMachine::getState 2019-12-15T13:37:52.086Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:37:52.151Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom 2019-12-15T13:37:52.156Z - info: Listing playlists 2019-12-15T13:37:52.157Z - info: CoreCommandRouter::volumioGetQueue 2019-12-15T13:37:52.158Z - info: CoreStateMachine::getQueue 2019-12-15T13:37:52.159Z - info: CorePlayQueue::getQueue 2019-12-15T13:37:52.161Z - info: CoreCommandRouter::volumioGetVisibleSources 2019-12-15T13:37:52.162Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:37:57.035Z - info: CoreCommandRouter::volumioGetState 2019-12-15T13:37:57.035Z - info: CoreStateMachine::getState 2019-12-15T13:37:57.036Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:37:58.340Z - info: Upmpdcli Daemon Started 2019-12-15T13:37:59.222Z - info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar 2019-12-15T13:37:59.223Z - info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar 2019-12-15T13:37:59.223Z - info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar 2019-12-15T13:37:59.224Z - info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar 2019-12-15T13:37:59.224Z - info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso 2019-12-15T13:37:59.224Z - info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso 2019-12-15T13:37:59.227Z - info: Adding plugin bluetooth to MyMusic Plugins 2019-12-15T13:37:59.229Z - info: Adding plugin cd_controller to MyMusic Plugins 2019-12-15T13:37:59.230Z - info: Adding plugin smart_inputs to MyMusic Plugins 2019-12-15T13:37:59.233Z - info: [MyVolumio PluginManager] Loading plugin "my_volumio"... 2019-12-15T13:38:00.659Z - info: [MyVolumio PluginManager] Loading plugin "streaming_services"... 2019-12-15T13:38:01.544Z - info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded 2019-12-15T13:38:01.545Z - info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio 2019-12-15T13:38:01.546Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:38:01.547Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:38:01.549Z - info: Starting MyVolumio Remote Streaming Endpoints 2019-12-15T13:38:01.571Z - info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded 2019-12-15T13:38:01.571Z - info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services 2019-12-15T13:38:01.573Z - info: Streaming services startup 2019-12-15T13:38:01.577Z - info: Starting Streaming Daemon 2019-12-15T13:38:01.606Z - info: [MyVolumio PluginManager] MyVolumio plugin successfully started 2019-12-15T13:38:02.367Z - info: MYVOLUMIO SUCCESSFULLY LOGGED IN 2019-12-15T13:38:02.370Z - info: MYVOLUMIO: Adding device 2019-12-15T13:38:02.371Z - info: MYVOLUMIO: Evaluating Server 2019-12-15T13:38:06.217Z - info: [MyVolumio PluginManager] Subscribed plan changed to virtuoso 2019-12-15T13:38:06.219Z - info: Removing browser output: myVolumio user plan is not superstar 2019-12-15T13:38:06.221Z - info: Removing audio output: 2019-12-15T13:38:06.227Z - info: Remote config written successfully 2019-12-15T13:38:06.228Z - info: Starting Tunnel 1 2019-12-15T13:38:06.230Z - info: Starting Tunnel Connection Checker 2019-12-15T13:38:06.281Z - info: Setting Geolocation for MyVolumio to eu1 2019-12-15T13:38:06.283Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:38:06.284Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:38:06.285Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:38:06.369Z - info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... 2019-12-15T13:38:06.374Z - info: MyVolumio status changed 2019-12-15T13:38:06.375Z - info: Streaming services startup 2019-12-15T13:38:06.377Z - info: Re-Starting Streaming Daemon 2019-12-15T13:38:06.387Z - info: Remote SSH Started 2019-12-15T13:38:06.550Z - info: Fetching Streaming Services browse cache 2019-12-15T13:38:06.571Z - info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid 2019-12-15T13:38:06.576Z - info: [MyVolumio PluginManager] Loading plugin "bluetooth"... 2019-12-15T13:38:06.739Z - info: [1576417086739] Starting BluetoothController 2019-12-15T13:38:06.848Z - info: [MyVolumio PluginManager] Loading plugin "cd_controller"... 2019-12-15T13:38:06.874Z - info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth 2019-12-15T13:38:06.875Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback 2019-12-15T13:38:06.898Z - info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller 2019-12-15T13:38:06.902Z - info: Adding CD REST API Endpoints 2019-12-15T13:38:06.904Z - info: Adding detectCD REST Endpoint for plugin: music_service/cd_controller 2019-12-15T13:38:06.905Z - info: Adding cdRemove REST Endpoint for plugin: music_service/cd_controller 2019-12-15T13:38:06.905Z - info: Adding cdPostScan REST Endpoint for plugin: music_service/cd_controller 2019-12-15T13:38:06.906Z - info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller 2019-12-15T13:38:06.907Z - info: Detecting CD presence 2019-12-15T13:38:06.956Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-15T13:38:06.957Z - info: [1576417086957] CoreMusicLibrary::Adding element TIDAL 2019-12-15T13:38:06.957Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:38:06.967Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesQOBUZ 2019-12-15T13:38:06.968Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:38:07.071Z - info: Bluetooth name changed to Volumio 2019-12-15T13:38:07.302Z - info: Updating MyVolumio device info 2019-12-15T13:38:07.302Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:38:07.303Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:38:07.303Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam 2019-12-15T13:38:07.311Z - info: CoreCommandRouter::volumioGetState 2019-12-15T13:38:07.311Z - info: CoreStateMachine::getState 2019-12-15T13:38:07.312Z - info: CorePlayQueue::getTrack 0 2019-12-15T13:38:10.076Z - info: Volumio BT Module successfully started 2019-12-15T13:38:11.182Z - info: Fetching Streaming Services browse cache 2019-12-15T13:38:11.202Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object] 2019-12-15T13:38:11.204Z - info: [1576417091203] CoreMusicLibrary::Adding element TIDAL 2019-12-15T13:38:11.206Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:38:11.213Z - info: CoreCommandRouter::volumioRemoveToBrowseSourcesQOBUZ 2019-12-15T13:38:11.215Z - info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources 2019-12-15T13:38:20.715Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion 2019-12-15T13:38:20.717Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam

tomstephens89 · December 15, 2019, 2:43pm

[b]UPDATE:

I believe the whole prefetch 500ms timeout thing to be a red herring. From what I read its been resolved and the errors printed in the log have been left in for debug reasons. I have uninstalled lastfm plugin again and playback works just fine.

It would appear that after a small random number of tracks, when the lastfm plugin attempts to scrobble, a portion of volumio crashes and runs through its startup procedure, audio playback keeps going until the track ends at which point the play state is STOPPED.

When this happens, the GUI locks up for a good number of seconds with the loading icon.[/b]

Any ideas here? I have no idea where to look and I’d love to scrobble my tracks to lastfm.

Saiyato · December 16, 2019, 3:43pm

Hi,

Good find, not sure where to look, since the plugin doens’t really hook into the system, it just consumes the API. So it connects to the following socket -> localhost:3000

Interesting part is the following:

2019-12-14T16:47:16.224Z - info: Tunnel connection is inactive, restarting it

I’m not sure what that does and if it’s a result or maybe causing the restarts. If it’s the cause, then, as you put it, it’s likely to be caused by the LastFM plugin. It could be egress, a fatal error, CPU usage or the connected socket in that case. At least that’s what I’m thinking

I also updated alot of code recently, can you try pulling the latest version from github? (1.3.3 as opposed to 1.2.9)
This might help, since I introduced some try-catches on strategic locations.

tomstephens89 · December 17, 2019, 8:03am

So after some discussion with Saiyato over on the github project page, he has solved this issue

Version 1.3.4 available in the github master.

Have played several albums in a queue and no issues like before!

Can Volumio devs issue a pull req to get the latest version into the gui plugin manager?