Play stops midway through queue since v2.444

In recent builds the player will stop at the end of a track even when there are more tracks in the queue. The web UI To continue playing I need to press the “next track” button in the web UI. This is running on a Raspberry Pi 1 B+ using an Arcam rDAC over USB.

I have uploaded two sets of logs. First set is from my preferred configuration while the player has hung at the end of a track: http://logs.volumio.org/volumio/sRdtJAQ.html

After this I performed a factory a reset, added my music library, no more modifications, and played the album again. It played fully without error, although I couldn’t hear it because the factory reset sets the output device to the audio jack and I don’t have any cable connected to the jack output.

Then I changed the audio output to “USB: ARCAM DAC” and played the queue again. This time it stopped after a couple of tracks. So the USB DAC seems to be important. Second set of logs from this state: http://logs.volumio.org/volumio/f0dtKIR.html And a screen grab of the playback view: https://pasteboard.co/HOQHPd9.png

I first experienced this after upgrading Volumio. After running all the recent builds I have identified the problem was introduced in v2.444. The previous version, v2.413, does not have this problem. All versions from 2.444 to the latest 2.502 have this problem.

In my config the music library is over the network, I have also experienced the problem when using a USB drive for the music files. And I have seen this problem with many different albums, not just the one used in the submitted logs.

Keep up the good work. Volumio is a brilliant addition to any hifi.

I confirm an issue described above. I have the similar configuration on latest V2.502 (both USB and NAS storages and USB audio DAC) and in my case playing of queue randomly stops in between the songs too.

I noticed this issue recently when setting up my new Volumio system, all the media is on an NFS share over wired ethernet, no network dropouts or anything.
Since changing the NFS mount options to use NFS v3 and with retrans=5 I haven’t had the issue again.
If you’re using NFS maybe the default mount options are different in your updated Volumio which will be something inherited from Raspbian/Debian.

The NFS mount options are added by editing the appropriate network drive under “My Music” and entering your options for the mount command to the Options field. I added the options ro,vers=3,retrans=5

Hope that helps.

  • Same here with 2.513 installed fresh yesterday on R-Pi 3B+,
  • Audio Injector stereo DAC (audioinjector-pi-soundcard),
  • MP3s on a USB thumb drive.

Indeed this is great stuff, but please let’s get this fixed so my wife can use it more.

Raspberry Pi B+
Volumio 2.513
USB DAC

I think I have what sounds like the same problem. When the WebUI is used the playlist will not complete and play will keep stopping randomly after a few tracks have played. When I use an MPD client like cantata this does not happen and everything works fine. Files are stored on a Server and shared with Samba (CIFS). From looking at the logs I think I have some idea of what is happening. The Volumio UI seems to be adding tracs to the MPD queue too slowly and causing MPD to stop when it has played all the files in its queue. After that Volumio continues to add tracks to the queue each minute or so , but now the player has stopped and I need to hit play again.

I have included the volumio log to show the problem. In this case an entire album with 15 tracks was added with the Volumio Web UI. In this case the first two tracks played but then MPD stopped. A check on the command line showed the MPD queue was empty so the player stopped. But then volumio went on to add the rest of the tracs over the next few minutes. Im wondering if there is any solution to this problem or if the old Raspberry Pi B+ is just too slow to keep up.

2018-12-17T02:36:04.007Z - info: CoreCommandRouter::volumioGetQueue
2018-12-17T02:36:04.011Z - info: CoreStateMachine::getQueue
2018-12-17T02:36:04.015Z - info: CorePlayQueue::getQueue
2018-12-17T02:36:08.540Z - info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri
2018-12-17T02:36:08.546Z - info: CURURI: music-library
2018-12-17T02:36:12.012Z - info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri
2018-12-17T02:36:12.018Z - info: CURURI: music-library/NAS
2018-12-17T02:36:13.185Z - info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri
2018-12-17T02:36:13.191Z - info: CURURI: music-library/NAS/audio
2018-12-17T02:36:21.267Z - info: CoreCommandRouter::executeOnPlugin: mpd , search
2018-12-17T02:36:23.451Z - info: All search sources collected, pushing search results
2018-12-17T02:36:35.811Z - info: CoreCommandRouter::volumioReplaceandPlayItems
2018-12-17T02:36:35.812Z - info: CoreStateMachine::ClearQueue
2018-12-17T02:36:35.814Z - info: CoreStateMachine::stop
2018-12-17T02:36:35.815Z - info: CoreStateMachine::setConsumeUpdateService undefined
2018-12-17T02:36:35.817Z - info: CorePlayQueue::clearPlayQueue
2018-12-17T02:36:35.819Z - info: CorePlayQueue::saveQueue
2018-12-17T02:36:35.832Z - info: CoreStateMachine::pushEmptyState
2018-12-17T02:36:35.833Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:36:35.835Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:36:35.951Z - info: CoreCommandRouter::volumioPushQueue
2018-12-17T02:36:35.958Z - info: CoreStateMachine::addQueueItems
2018-12-17T02:36:35.959Z - info: CorePlayQueue::addQueueItems
2018-12-17T02:36:35.975Z - info: Adding Item to queue: albums://Taylor%20Swift/reputation
2018-12-17T02:36:35.981Z - info: Exploding uri albums://Taylor%20Swift/reputation in service mpd
2018-12-17T02:36:36.257Z - info: CorePlayQueue::saveQueue
2018-12-17T02:36:36.275Z - info: CoreCommandRouter::volumioPushQueue
2018-12-17T02:36:36.333Z - info: CoreStateMachine::updateTrackBlock
2018-12-17T02:36:36.338Z - info: CorePlayQueue::getTrackBlock
2018-12-17T02:36:36.351Z - info: CoreCommandRouter::volumioPlay
2018-12-17T02:36:36.353Z - info: CoreStateMachine::play index 0
2018-12-17T02:36:36.354Z - info: CoreStateMachine::setConsumeUpdateService undefined
2018-12-17T02:36:36.356Z - info: CoreStateMachine::stop
2018-12-17T02:36:36.357Z - info: CoreStateMachine::setConsumeUpdateService undefined
2018-12-17T02:36:36.360Z - info: CoreStateMachine::play index undefined
2018-12-17T02:36:36.393Z - info: CoreStateMachine::setConsumeUpdateService undefined
2018-12-17T02:36:36.394Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:36:36.396Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T02:36:36.397Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:36:36.400Z - info: ControllerMpd::clearAddPlayTracks NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/01 - ...Ready For It.flac
2018-12-17T02:36:36.411Z - info: ControllerMpd::sendMpdCommand stop
2018-12-17T02:36:36.418Z - info: sending command...
2018-12-17T02:36:36.451Z - info: parsing response...
2018-12-17T02:36:36.454Z - info: ControllerMpd::sendMpdCommand clear
2018-12-17T02:36:36.455Z - info: sending command...
2018-12-17T02:36:36.538Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:36:36.540Z - info: Ignoring MPD Status Update
2018-12-17T02:36:36.542Z - info: parsing response...
2018-12-17T02:36:36.544Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/01 - ...Ready For It.flac"
2018-12-17T02:36:36.573Z - info: sending command...
2018-12-17T02:36:36.579Z - info: 
2018-12-17T02:36:36.590Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:36:36.602Z - info: Ignoring MPD Status Update
2018-12-17T02:36:36.604Z - info: ------------------------------ 81ms
2018-12-17T02:36:36.606Z - info: parsing response...
2018-12-17T02:36:36.608Z - info: ControllerMpd::sendMpdCommand play
2018-12-17T02:36:36.623Z - info: sending command...
2018-12-17T02:36:36.736Z - info: ------------------------------ 129ms
2018-12-17T02:36:36.743Z - info: parsing response...
2018-12-17T02:36:41.033Z - info: 
---------------------------- MPD announces state update: player
2018-12-17T02:36:41.054Z - info: ControllerMpd::getState
2018-12-17T02:36:41.064Z - info: ControllerMpd::sendMpdCommand status
2018-12-17T02:36:41.075Z - info: sending command...
2018-12-17T02:36:41.155Z - info: 
---------------------------- MPD announces state update: player
2018-12-17T02:36:41.159Z - info: ControllerMpd::getState
2018-12-17T02:36:41.181Z - info: ControllerMpd::sendMpdCommand status
2018-12-17T02:36:41.196Z - info: parsing response...
2018-12-17T02:36:41.234Z - info: sending command...
2018-12-17T02:36:41.267Z - info: ControllerMpd::parseState
2018-12-17T02:36:41.270Z - info: ControllerMpd::sendMpdCommand playlistinfo
2018-12-17T02:36:41.312Z - info: sending command...
2018-12-17T02:36:41.426Z - info: parsing response...
2018-12-17T02:36:41.430Z - info: parsing response...
2018-12-17T02:36:41.497Z - info: ControllerMpd::parseState
2018-12-17T02:36:41.499Z - info: ControllerMpd::sendMpdCommand playlistinfo
2018-12-17T02:36:41.523Z - info: ControllerMpd::parseTrackInfo
2018-12-17T02:36:41.528Z - info: sending command...
2018-12-17T02:36:41.591Z - info: ControllerMpd::pushState
2018-12-17T02:36:41.593Z - info: CoreCommandRouter::servicePushState
2018-12-17T02:36:41.595Z - info: CoreStateMachine::syncState
2018-12-17T02:36:41.597Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:36:41.633Z - info: STATE SERVICE {"status":"play","position":0,"seek":3459,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"...Ready For It?","artist":"Taylor Swift","album":"reputation","uri":"NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/01 - ...Ready For It.flac","trackType":"flac"}
2018-12-17T02:36:41.635Z - info: CURRENT POSITION 0
2018-12-17T02:36:41.637Z - info: CoreStateMachine::syncState   stateService play
2018-12-17T02:36:41.639Z - info: CoreStateMachine::syncState   currentStatus stop
2018-12-17T02:36:41.693Z - info: CoreStateMachine::pushState
2018-12-17T02:36:41.695Z - info: CoreStateMachine::getState
2018-12-17T02:36:41.731Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:36:41.733Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:36:41.735Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:36:42.528Z - info: ------------------------------ 1469ms
2018-12-17T02:36:42.654Z - info: parsing response...
2018-12-17T02:36:42.705Z - info: ControllerMpd::parseTrackInfo
2018-12-17T02:36:42.751Z - info: ControllerMpd::pushState
2018-12-17T02:36:42.762Z - info: CoreCommandRouter::servicePushState
2018-12-17T02:36:42.809Z - info: CoreStateMachine::syncState
2018-12-17T02:36:42.827Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:36:42.829Z - info: STATE SERVICE {"status":"play","position":0,"seek":3599,"duration":208,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"...Ready For It?","artist":"Taylor Swift","album":"reputation","uri":"NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/01 - ...Ready For It.flac","trackType":"flac"}
2018-12-17T02:36:42.847Z - info: CURRENT POSITION 0
2018-12-17T02:36:42.864Z - info: CoreStateMachine::syncState   stateService play
2018-12-17T02:36:42.865Z - info: CoreStateMachine::syncState   currentStatus play
2018-12-17T02:36:42.867Z - info: Received an update from plugin. extracting info from payload
2018-12-17T02:36:42.938Z - info: CoreStateMachine::pushState
2018-12-17T02:36:42.964Z - info: CoreStateMachine::getState
2018-12-17T02:36:42.966Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:36:43.040Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:36:43.042Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:36:43.778Z - info: CoreStateMachine::pushState
2018-12-17T02:36:43.780Z - info: CoreStateMachine::getState
2018-12-17T02:36:43.792Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:36:43.794Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:36:43.796Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:36:45.180Z - info: ------------------------------ 3925ms
2018-12-17T02:40:02.202Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:40:02.204Z - info: CorePlayQueue::getTrack 1
2018-12-17T02:40:02.206Z - info: Prefetching next song
2018-12-17T02:40:02.208Z - info: DOING PREFETCH IN MPD
2018-12-17T02:40:02.210Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/02 - End Game (feat. Ed Sheeran & Future).flac"
2018-12-17T02:40:02.223Z - info: sending command...
2018-12-17T02:40:02.342Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:40:02.356Z - info: Ignoring MPD Status Update
2018-12-17T02:40:02.397Z - info: parsing response...
2018-12-17T02:40:02.411Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T02:40:02.467Z - info: sending command...
2018-12-17T02:40:02.671Z - info: ------------------------------ 342ms
2018-12-17T02:40:02.673Z - info: parsing response...
2018-12-17T02:40:05.874Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:40:05.877Z - info: Ignoring MPD Status Update
2018-12-17T02:40:05.879Z - info: 
---------------------------- MPD announces state update: player
2018-12-17T02:40:05.915Z - info: ControllerMpd::getState
2018-12-17T02:40:05.917Z - info: ControllerMpd::sendMpdCommand status
2018-12-17T02:40:05.952Z - info: sending command...
2018-12-17T02:40:05.993Z - info: ------------------------------ 89ms
2018-12-17T02:40:06.018Z - info: parsing response...
2018-12-17T02:40:06.063Z - info: ControllerMpd::parseState
2018-12-17T02:40:06.066Z - info: ControllerMpd::sendMpdCommand playlistinfo
2018-12-17T02:40:06.069Z - info: sending command...
2018-12-17T02:40:06.120Z - info: parsing response...
2018-12-17T02:40:06.130Z - info: ControllerMpd::parseTrackInfo
2018-12-17T02:40:06.149Z - info: ControllerMpd::pushState
2018-12-17T02:40:06.165Z - info: CoreCommandRouter::servicePushState
2018-12-17T02:40:06.166Z - info: CoreStateMachine::syncState
2018-12-17T02:40:06.168Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:40:06.193Z - info: STATE SERVICE {"status":"play","position":0,"seek":69,"duration":245,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"End Game (feat. Ed Sheeran & Future)","artist":"Taylor Swift","album":"reputation","uri":"NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/02 - End Game (feat. Ed Sheeran & Future).flac","trackType":"flac"}
2018-12-17T02:40:06.213Z - info: CURRENT POSITION 0
2018-12-17T02:40:06.220Z - info: CoreStateMachine::syncState   stateService play
2018-12-17T02:40:06.233Z - info: CoreStateMachine::syncState   currentStatus play
2018-12-17T02:40:06.235Z - info: Received an update from plugin. extracting info from payload
2018-12-17T02:40:06.237Z - info: CoreStateMachine::pushState
2018-12-17T02:40:06.239Z - info: CoreStateMachine::getState
2018-12-17T02:40:06.273Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:40:06.275Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:40:06.277Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:40:06.909Z - info: CoreStateMachine::pushState
2018-12-17T02:40:06.924Z - info: CoreStateMachine::getState
2018-12-17T02:40:06.942Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:40:06.944Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:40:06.946Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:40:07.558Z - info: ------------------------------ 1642ms
2018-12-17T02:44:11.160Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:44:11.162Z - info: Ignoring MPD Status Update
2018-12-17T02:44:11.164Z - info: 
---------------------------- MPD announces state update: player
2018-12-17T02:44:11.166Z - info: ControllerMpd::getState
2018-12-17T02:44:11.168Z - info: ControllerMpd::sendMpdCommand status
2018-12-17T02:44:11.180Z - info: sending command...
2018-12-17T02:44:11.185Z - info: 
2018-12-17T02:44:11.188Z - info: ------------------------------ 35ms
2018-12-17T02:44:11.189Z - info: parsing response...
2018-12-17T02:44:11.202Z - info: ControllerMpd::parseState
2018-12-17T02:44:11.204Z - info: ControllerMpd::pushState
2018-12-17T02:44:11.205Z - info: CoreCommandRouter::servicePushState
2018-12-17T02:44:11.206Z - info: CoreStateMachine::syncState
2018-12-17T02:44:11.252Z - info: CoreStateMachine::pushState
2018-12-17T02:44:11.254Z - info: CoreStateMachine::getState
2018-12-17T02:44:11.255Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:44:11.256Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:44:11.257Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:44:11.361Z - info: CorePlayQueue::getTrack 0
2018-12-17T02:44:11.366Z - 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}
2018-12-17T02:44:11.381Z - info: CURRENT POSITION 0
2018-12-17T02:44:11.386Z - info: CoreStateMachine::syncState   stateService stop
2018-12-17T02:44:11.388Z - info: CoreStateMachine::syncState   currentStatus play
2018-12-17T02:44:11.389Z - info: CURRENT POSITION 0
2018-12-17T02:44:11.397Z - info: CURRENT POSITION 1
2018-12-17T02:44:11.399Z - info: CoreStateMachine::pushState
2018-12-17T02:44:11.400Z - info: CoreStateMachine::getState
2018-12-17T02:44:11.425Z - info: CorePlayQueue::getTrack 1
2018-12-17T02:44:11.427Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:44:11.428Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:44:11.594Z - info: Prefetch done, skipping queuing
2018-12-17T02:44:11.596Z - info: CoreStateMachine::pushState
2018-12-17T02:44:11.597Z - info: CoreStateMachine::getState
2018-12-17T02:44:11.598Z - info: CorePlayQueue::getTrack 1
2018-12-17T02:44:11.600Z - info: CoreCommandRouter::volumioPushState
2018-12-17T02:44:11.633Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2018-12-17T02:44:11.964Z - info: ------------------------------ 774ms
2018-12-17T02:47:34.214Z - info: CorePlayQueue::getTrack 1
2018-12-17T02:47:34.221Z - info: CorePlayQueue::getTrack 2
2018-12-17T02:47:34.222Z - info: Prefetching next song
2018-12-17T02:47:34.224Z - info: DOING PREFETCH IN MPD
2018-12-17T02:47:34.225Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/03 - I Did Something Bad.flac"
2018-12-17T02:47:34.227Z - info: sending command...
2018-12-17T02:47:34.245Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:47:34.247Z - info: Ignoring MPD Status Update
2018-12-17T02:47:34.253Z - info: parsing response...
2018-12-17T02:47:34.255Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T02:47:34.271Z - info: sending command...
2018-12-17T02:47:34.278Z - info: ------------------------------ 33ms
2018-12-17T02:47:34.279Z - info: parsing response...
2018-12-17T02:47:38.742Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T02:47:38.744Z - info: CorePlayQueue::getTrack 2
2018-12-17T02:51:31.941Z - info: CorePlayQueue::getTrack 2
2018-12-17T02:51:31.942Z - info: CorePlayQueue::getTrack 3
2018-12-17T02:51:31.944Z - info: Prefetching next song
2018-12-17T02:51:31.945Z - info: DOING PREFETCH IN MPD
2018-12-17T02:51:31.983Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/04 - Don’t Blame Me.flac"
2018-12-17T02:51:31.988Z - info: sending command...
2018-12-17T02:51:32.001Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:51:32.002Z - info: Ignoring MPD Status Update
2018-12-17T02:51:32.004Z - info: parsing response...
2018-12-17T02:51:32.006Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T02:51:32.022Z - info: sending command...
2018-12-17T02:51:32.029Z - info: ------------------------------ 34ms
2018-12-17T02:51:32.037Z - info: parsing response...
2018-12-17T02:51:36.504Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T02:51:36.506Z - info: CorePlayQueue::getTrack 3
2018-12-17T02:55:27.548Z - info: CorePlayQueue::getTrack 3
2018-12-17T02:55:27.550Z - info: CorePlayQueue::getTrack 4
2018-12-17T02:55:27.552Z - info: Prefetching next song
2018-12-17T02:55:27.553Z - info: DOING PREFETCH IN MPD
2018-12-17T02:55:27.555Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/05 - Delicate.flac"
2018-12-17T02:55:27.559Z - info: sending command...
2018-12-17T02:55:27.585Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:55:27.588Z - info: Ignoring MPD Status Update
2018-12-17T02:55:27.601Z - info: parsing response...
2018-12-17T02:55:27.604Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T02:55:27.612Z - info: sending command...
2018-12-17T02:55:27.628Z - info: ------------------------------ 43ms
2018-12-17T02:55:27.629Z - info: parsing response...
2018-12-17T02:55:32.074Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T02:55:32.076Z - info: CorePlayQueue::getTrack 4
2018-12-17T02:59:19.350Z - info: CorePlayQueue::getTrack 4
2018-12-17T02:59:19.352Z - info: CorePlayQueue::getTrack 5
2018-12-17T02:59:19.353Z - info: Prefetching next song
2018-12-17T02:59:19.355Z - info: DOING PREFETCH IN MPD
2018-12-17T02:59:19.356Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/06 - Look What You Made Me Do.flac"
2018-12-17T02:59:19.358Z - info: sending command...
2018-12-17T02:59:19.376Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T02:59:19.378Z - info: Ignoring MPD Status Update
2018-12-17T02:59:19.391Z - info: parsing response...
2018-12-17T02:59:19.394Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T02:59:19.398Z - info: sending command...
2018-12-17T02:59:19.406Z - info: ------------------------------ 30ms
2018-12-17T02:59:19.407Z - info: parsing response...
2018-12-17T02:59:23.621Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T02:59:23.623Z - info: CorePlayQueue::getTrack 5
2018-12-17T03:02:50.690Z - info: CorePlayQueue::getTrack 5
2018-12-17T03:02:50.692Z - info: CorePlayQueue::getTrack 6
2018-12-17T03:02:50.693Z - info: Prefetching next song
2018-12-17T03:02:50.695Z - info: DOING PREFETCH IN MPD
2018-12-17T03:02:50.696Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/07 - So It Goes....flac"
2018-12-17T03:02:50.698Z - info: sending command...
2018-12-17T03:02:50.715Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:02:50.717Z - info: Ignoring MPD Status Update
2018-12-17T03:02:50.732Z - info: parsing response...
2018-12-17T03:02:50.734Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:02:50.738Z - info: sending command...
2018-12-17T03:02:50.746Z - info: ------------------------------ 32ms
2018-12-17T03:02:50.748Z - info: parsing response...
2018-12-17T03:02:55.209Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:02:55.217Z - info: CorePlayQueue::getTrack 6
2018-12-17T03:06:38.265Z - info: CorePlayQueue::getTrack 6
2018-12-17T03:06:38.272Z - info: CorePlayQueue::getTrack 7
2018-12-17T03:06:38.274Z - info: Prefetching next song
2018-12-17T03:06:38.275Z - info: DOING PREFETCH IN MPD
2018-12-17T03:06:38.276Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/08 - Gorgeous.flac"
2018-12-17T03:06:38.278Z - info: sending command...
2018-12-17T03:06:38.295Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:06:38.297Z - info: Ignoring MPD Status Update
2018-12-17T03:06:38.311Z - info: parsing response...
2018-12-17T03:06:38.314Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:06:38.319Z - info: sending command...
2018-12-17T03:06:38.362Z - info: ------------------------------ 63ms
2018-12-17T03:06:38.363Z - info: parsing response...
2018-12-17T03:06:42.788Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:06:42.794Z - info: CorePlayQueue::getTrack 7
2018-12-17T03:10:08.046Z - info: CorePlayQueue::getTrack 7
2018-12-17T03:10:08.052Z - info: CorePlayQueue::getTrack 8
2018-12-17T03:10:08.054Z - info: Prefetching next song
2018-12-17T03:10:08.055Z - info: DOING PREFETCH IN MPD
2018-12-17T03:10:08.057Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/09 - Getaway Car.flac"
2018-12-17T03:10:08.058Z - info: sending command...
2018-12-17T03:10:08.075Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:10:08.076Z - info: Ignoring MPD Status Update
2018-12-17T03:10:08.092Z - info: parsing response...
2018-12-17T03:10:08.094Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:10:08.099Z - info: sending command...
2018-12-17T03:10:08.108Z - info: ------------------------------ 33ms
2018-12-17T03:10:08.109Z - info: parsing response...
2018-12-17T03:10:12.324Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:10:12.326Z - info: CorePlayQueue::getTrack 8
2018-12-17T03:14:01.455Z - info: CorePlayQueue::getTrack 8
2018-12-17T03:14:01.457Z - info: CorePlayQueue::getTrack 9
2018-12-17T03:14:01.458Z - info: Prefetching next song
2018-12-17T03:14:01.460Z - info: DOING PREFETCH IN MPD
2018-12-17T03:14:01.471Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/10 - King of My Heart.flac"
2018-12-17T03:14:01.473Z - info: sending command...
2018-12-17T03:14:01.479Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:14:01.491Z - info: Ignoring MPD Status Update
2018-12-17T03:14:01.493Z - info: parsing response...
2018-12-17T03:14:01.495Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:14:01.501Z - info: sending command...
2018-12-17T03:14:01.518Z - info: ------------------------------ 39ms
2018-12-17T03:14:01.519Z - info: parsing response...
2018-12-17T03:14:05.987Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:14:05.989Z - info: CorePlayQueue::getTrack 9
2018-12-17T03:17:35.071Z - info: CorePlayQueue::getTrack 9
2018-12-17T03:17:35.073Z - info: CorePlayQueue::getTrack 10
2018-12-17T03:17:35.074Z - info: Prefetching next song
2018-12-17T03:17:35.076Z - info: DOING PREFETCH IN MPD
2018-12-17T03:17:35.077Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/11 - Dancing With Our Hands Tied.flac"
2018-12-17T03:17:35.092Z - info: sending command...
2018-12-17T03:17:35.107Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:17:35.118Z - info: Ignoring MPD Status Update
2018-12-17T03:17:35.120Z - info: parsing response...
2018-12-17T03:17:35.123Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:17:35.135Z - info: sending command...
2018-12-17T03:17:35.159Z - info: ------------------------------ 44ms
2018-12-17T03:17:35.160Z - info: parsing response...
2018-12-17T03:17:39.603Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:17:39.608Z - info: CorePlayQueue::getTrack 10
2018-12-17T03:21:06.780Z - info: CorePlayQueue::getTrack 10
2018-12-17T03:21:06.782Z - info: CorePlayQueue::getTrack 11
2018-12-17T03:21:06.783Z - info: Prefetching next song
2018-12-17T03:21:06.785Z - info: DOING PREFETCH IN MPD
2018-12-17T03:21:06.786Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/12 - Dress.flac"
2018-12-17T03:21:06.788Z - info: sending command...
2018-12-17T03:21:06.805Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:21:06.807Z - info: Ignoring MPD Status Update
2018-12-17T03:21:06.821Z - info: parsing response...
2018-12-17T03:21:06.823Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:21:06.829Z - info: sending command...
2018-12-17T03:21:06.839Z - info: ------------------------------ 34ms
2018-12-17T03:21:06.851Z - info: parsing response...
2018-12-17T03:21:11.301Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:21:11.307Z - info: CorePlayQueue::getTrack 11
2018-12-17T03:24:56.516Z - info: CorePlayQueue::getTrack 11
2018-12-17T03:24:56.517Z - info: CorePlayQueue::getTrack 12
2018-12-17T03:24:56.519Z - info: Prefetching next song
2018-12-17T03:24:56.520Z - info: DOING PREFETCH IN MPD
2018-12-17T03:24:56.532Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/13 - This Is Why We Can’t Have Nice Things.flac"
2018-12-17T03:24:56.533Z - info: sending command...
2018-12-17T03:24:56.539Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:24:56.551Z - info: Ignoring MPD Status Update
2018-12-17T03:24:56.553Z - info: parsing response...
2018-12-17T03:24:56.555Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:24:56.561Z - info: sending command...
2018-12-17T03:24:56.577Z - info: ------------------------------ 38ms
2018-12-17T03:24:56.579Z - info: parsing response...
2018-12-17T03:25:01.055Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:25:01.057Z - info: CorePlayQueue::getTrack 12
2018-12-17T03:28:23.110Z - info: CorePlayQueue::getTrack 12
2018-12-17T03:28:23.112Z - info: CorePlayQueue::getTrack 13
2018-12-17T03:28:23.113Z - info: Prefetching next song
2018-12-17T03:28:23.114Z - info: DOING PREFETCH IN MPD
2018-12-17T03:28:23.116Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/14 - Call It What You Want.flac"
2018-12-17T03:28:23.118Z - info: sending command...
2018-12-17T03:28:23.135Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:28:23.137Z - info: Ignoring MPD Status Update
2018-12-17T03:28:23.151Z - info: parsing response...
2018-12-17T03:28:23.153Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:28:23.159Z - info: sending command...
2018-12-17T03:28:23.180Z - info: ------------------------------ 35ms
2018-12-17T03:28:23.182Z - info: parsing response...
2018-12-17T03:28:27.629Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:28:27.631Z - info: CorePlayQueue::getTrack 13
2018-12-17T03:31:46.757Z - info: CorePlayQueue::getTrack 13
2018-12-17T03:31:46.759Z - info: CorePlayQueue::getTrack 14
2018-12-17T03:31:46.763Z - info: Prefetching next song
2018-12-17T03:31:46.764Z - info: DOING PREFETCH IN MPD
2018-12-17T03:31:46.766Z - info: ControllerMpd::sendMpdCommand add "NAS/audio/Lossless/not-backed-up/Taylor.Swift-Reputation.2017. [FLAC]/15 - New Year’s Day.flac"
2018-12-17T03:31:46.768Z - info: sending command...
2018-12-17T03:31:46.780Z - info: 
---------------------------- MPD announces system playlist update
2018-12-17T03:31:46.792Z - info: Ignoring MPD Status Update
2018-12-17T03:31:46.794Z - info: parsing response...
2018-12-17T03:31:46.796Z - info: ControllerMpd::sendMpdCommand consume 1
2018-12-17T03:31:46.802Z - info: sending command...
2018-12-17T03:31:46.819Z - info: ------------------------------ 39ms
2018-12-17T03:31:46.820Z - info: parsing response...
2018-12-17T03:31:51.281Z - info: CoreStateMachine::startPlaybackTimer
2018-12-17T03:31:51.283Z - info: CorePlayQueue::getTrack 14
2018-12-17T03:35:41.362Z - info: CorePlayQueue::getTrack 14
2018-12-17T03:35:41.363Z - info: CorePlayQueue::getTrack 15

Hi,

Same problem here since the last update…

Tested with rpi 3b and rpi zero w…

Queue list stop playing randomly

mp3, flac on USB Drive

thx

hi there, pb still here :cry:

this bug is really boring…

Someone could give me a volumio version without this issue please ?

You might try 2.413 , also setting the USB speed to 1 with ‘dwc_otg.speed=1’ seems to help as well. You can also just bypass the Volumio UI and use an mpd client https://www.musicpd.org/clients/

Obviously this is not a common problem since few seem to be reporting it. But it happens reliably on my device , and Ive tried two different USB dacs and a half dozen different volumio images.

It’s not always clear when the playback stops, can be after the first two songs, or after a dozen.

Here some logs:

From what I can see, normally 5s before the end of the song, the next song is scheduled to start (“prefetched”), and 5s later you see the mpd update:

Mar 19 19:29:03 volumio-pi-living volumio[1059]: info: CorePlayQueue::getTrack 19
Mar 19 19:29:03 volumio-pi-living volumio[1059]: info: Prefetching next song
Mar 19 19:29:03 volumio-pi-living volumio[1059]: info: DOING PREFETCH IN MPD
....
Mar 19 19:29:08 volumio-pi-living volumio[1059]: info: STATE SERVICE {"status":"play","position":0,"seek":46,"duration":191,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"Sundance","artist":"Novastar","album":"Almost Bangor","uri":"NAS/Music-flac/Music Pop Rock Library/...","trackType":"flac"}

BUT when playing of the next song fails, I don’t see any prefetch log, only a status update returning an empty MPD playlist:

Mar 19 19:32:19 volumio-pi-living volumio[1059]: info:
Mar 19 19:32:19 volumio-pi-living volumio[1059]: ---------------------------- MPD announces system playlist update
Mar 19 19:32:19 volumio-pi-living volumio[1059]: info: Ignoring MPD Status Update
Mar 19 19:32:19 volumio-pi-living volumio[1059]: info:
Mar 19 19:32:19 volumio-pi-living volumio[1059]: ---------------------------- MPD announces state update: player
Mar 19 19:32:19 volumio-pi-living volumio[1059]: info: ControllerMpd::getState
Mar 19 19:32:19 volumio-pi-living volumio[1059]: info: ControllerMpd::sendMpdCommand status
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: sending command...
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info:
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: ------------------------------ 84ms
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: parsing response...
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: ControllerMpd::parseState
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: ControllerMpd::pushState
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CoreCommandRouter::servicePushState
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CoreStateMachine::syncState
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CoreStateMachine::pushState
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CoreStateMachine::getState
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CorePlayQueue::getTrack 18
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CoreCommandRouter::volumioPushState
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CorePlayQueue::getTrack 18
Mar 19 19:32:20 volumio-pi-living volumio[1059]: 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}
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CURRENT POSITION 18
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CoreStateMachine::syncState   stateService stop
Mar 19 19:32:20 volumio-pi-living volumio[1059]: info: CoreStateMachine::syncState   currentStatus play

my first search points to https://github.com/volumio/Volumio2/blob/master/app/statemachine.js#L445

could it be that the fixes to the incorrect seekTime caused this regression? e.g. https://volumio.org/forum/bugs-statemachine-increaseplaybacktimer-method-t10340.html

Anyway, I’m continuing my investigations, but any help is appreciated. :slight_smile:

I added some extra debug logging to “statemachine.js” to investigate the issue:

CoreStateMachine.prototype.increasePlaybackTimer = function () {
        var self=this;

        var now=Date.now();
        this.currentSeek+=(now-this.playbackStart);

        if(this.runPlaybackTimer==true)
        {
                this.playbackStart=Date.now();


                var remainingTime=this.currentSongDuration-this.currentSeek;
 //// temp debug logging
               this.commandRouter.pushConsoleMessage("this.currentSongDuration:"+this.currentSongDuration+" - this.currentSeek:"+this.currentSeek+" - remainingTime:"+ remainingTime+" - this.askedForPrefetch:"+this.askedForPrefetch);
                if(remainingTime>=0 && remainingTime<5000 && this.askedForPrefetch==false)
                {
                        this.askedForPrefetch=true;

                        var trackBlock = this.getTrack(this.currentPosition);

            var nextIndex=this.getNextIndex();

            var nextTrackBlock = this.getTrack(nextIndex);
//// temp debug logging
                this.commandRouter.pushConsoleMessage("nextTrackBlock:"+nextTrackBlock+" - nextIndex:"+nextIndex+" - trackBlock:"+ trackBlock);
                        if(nextTrackBlock!==undefined && nextTrackBlock!==null && nextTrackBlock.service==trackBlock.service)
                        {
                this.commandRouter.pushConsoleMessage("Prefetching next song");

                                var plugin = this.commandRouter.pluginManager.getPlugin('music_service', trackBlock.service);
                                if(plugin && typeof(plugin.prefetch) === typeof(Function))
                                {
                                        this.prefetchDone=true;
                                        plugin.prefetch(nextTrackBlock);
                                }
                        }
                }

when the playback is ok, the log is as expected: e.g.:

2019-03-20T08:14:28.636Z - info: this.currentSongDuration:210000 - this.currentSeek:202200 - remainingTime:7800 - this.askedForPrefetch:false
2019-03-20T08:14:28.896Z - info: this.currentSongDuration:210000 - this.currentSeek:202459 - remainingTime:7541 - this.askedForPrefetch:false
2019-03-20T08:14:29.159Z - info: this.currentSongDuration:210000 - this.currentSeek:202722 - remainingTime:7278 - this.askedForPrefetch:false
2019-03-20T08:14:29.418Z - info: this.currentSongDuration:210000 - this.currentSeek:202983 - remainingTime:7017 - this.askedForPrefetch:false
2019-03-20T08:14:29.681Z - info: this.currentSongDuration:210000 - this.currentSeek:203244 - remainingTime:6756 - this.askedForPrefetch:false
2019-03-20T08:14:29.942Z - info: this.currentSongDuration:210000 - this.currentSeek:203505 - remainingTime:6495 - this.askedForPrefetch:false
2019-03-20T08:14:30.202Z - info: this.currentSongDuration:210000 - this.currentSeek:203765 - remainingTime:6235 - this.askedForPrefetch:false
2019-03-20T08:14:30.467Z - info: this.currentSongDuration:210000 - this.currentSeek:204032 - remainingTime:5968 - this.askedForPrefetch:false

But transitioning to the next song, apparently the currentSongDuration doesn’t get updated. Although the next song is 234s, the currentSongDuration remains at 210000 and the currentSeek is not reset causing negative “remainingTime” calculations:

2019-03-20T08:14:31.509Z - info: this.currentSongDuration:210000 - this.currentSeek:205072 - remainingTime:4928 - this.askedForPrefetch:false
2019-03-20T08:14:31.513Z - info: CorePlayQueue::getTrack 5
2019-03-20T08:14:31.536Z - info: CorePlayQueue::getTrack 6
2019-03-20T08:14:31.539Z - info: nextTrackBlock:[object Object] - nextIndex:6 - trackBlock:[object Object]
2019-03-20T08:14:31.541Z - info: Prefetching next song
2019-03-20T08:14:31.560Z - info: DOING PREFETCH IN MPD
2019-03-20T08:14:31.563Z - info: ControllerMpd::sendMpdCommand add "NAS/Music-flac/Music Pop Rock Library/Nolwenn Leroy/Histoires naturelles/07 Mystère.flac"
2019-03-20T08:14:31.605Z - info: sending command...
2019-03-20T08:14:31.678Z - info: 
---------------------------- MPD announces system playlist update
2019-03-20T08:14:31.683Z - info: Ignoring MPD Status Update
2019-03-20T08:14:31.699Z - info: parsing response...
2019-03-20T08:14:31.731Z - info: ControllerMpd::sendMpdCommand consume 1
2019-03-20T08:14:31.777Z - info: sending command...
2019-03-20T08:14:31.844Z - info: 
---------------------------- MPD announces state update: options
2019-03-20T08:14:31.858Z - info: ------------------------------ 189ms
2019-03-20T08:14:31.868Z - info: parsing response...
2019-03-20T08:14:31.871Z - info: ControllerMpd::getState
2019-03-20T08:14:31.873Z - info: ControllerMpd::sendMpdCommand status
2019-03-20T08:14:31.911Z - info: sending command...
2019-03-20T08:14:31.939Z - info: this.currentSongDuration:210000 - this.currentSeek:205506 - remainingTime:4494 - this.askedForPrefetch:true
2019-03-20T08:14:31.981Z - info: parsing response...
2019-03-20T08:14:32.011Z - info: ControllerMpd::parseState
2019-03-20T08:14:32.014Z - info: ControllerMpd::sendMpdCommand playlistinfo
2019-03-20T08:14:32.027Z - info: sending command...
2019-03-20T08:14:32.104Z - info: parsing response...
2019-03-20T08:14:32.136Z - info: ControllerMpd::parseTrackInfo
2019-03-20T08:14:32.171Z - info: ControllerMpd::pushState
2019-03-20T08:14:32.187Z - info: CoreCommandRouter::servicePushState
2019-03-20T08:14:32.195Z - info: CoreStateMachine::syncState
2019-03-20T08:14:32.209Z - info: CorePlayQueue::getTrack 5
2019-03-20T08:14:32.235Z - info: STATE SERVICE {"status":"play","position":0,"seek":206866,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"Rien de mieux au monde","artist":"Nolwenn Leroy","album":"Histoires naturelles","uri":"NAS/Music-flac/Music Pop Rock Library/...","trackType":"flac"}
2019-03-20T08:14:32.238Z - info: CURRENT POSITION 5
2019-03-20T08:14:32.240Z - info: CoreStateMachine::syncState   stateService play
2019-03-20T08:14:32.242Z - info: CoreStateMachine::syncState   currentStatus play
2019-03-20T08:14:32.278Z - info: Received an update from plugin. extracting info from payload
2019-03-20T08:14:32.280Z - info: CoreStateMachine::pushState
2019-03-20T08:14:32.282Z - info: CoreStateMachine::getState
2019-03-20T08:14:32.303Z - info: CorePlayQueue::getTrack 5
2019-03-20T08:14:32.305Z - info: CoreCommandRouter::volumioPushState
2019-03-20T08:14:32.330Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-03-20T08:14:32.961Z - info: CoreStateMachine::pushState
2019-03-20T08:14:32.988Z - info: CoreStateMachine::getState
2019-03-20T08:14:32.995Z - info: CorePlayQueue::getTrack 5
2019-03-20T08:14:33.026Z - info: CoreCommandRouter::volumioPushState
2019-03-20T08:14:33.029Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-03-20T08:14:34.181Z - info: ------------------------------ 2360ms
2019-03-20T08:14:34.275Z - info: this.currentSongDuration:210000 - this.currentSeek:207828 - remainingTime:2172 - this.askedForPrefetch:true
2019-03-20T08:14:34.641Z - info: this.currentSongDuration:210000 - this.currentSeek:208184 - remainingTime:1816 - this.askedForPrefetch:true
2019-03-20T08:14:34.892Z - info: 
---------------------------- MPD announces system playlist update
2019-03-20T08:14:34.903Z - info: Ignoring MPD Status Update
2019-03-20T08:14:34.905Z - info: 
---------------------------- MPD announces state update: player
2019-03-20T08:14:34.964Z - info: ControllerMpd::getState
2019-03-20T08:14:35.006Z - info: ControllerMpd::sendMpdCommand status
2019-03-20T08:14:35.076Z - info: sending command...
2019-03-20T08:14:35.109Z - info: this.currentSongDuration:210000 - this.currentSeek:208649 - remainingTime:1351 - this.askedForPrefetch:true
2019-03-20T08:14:35.220Z - info: ------------------------------ 334ms
2019-03-20T08:14:35.244Z - info: parsing response...
2019-03-20T08:14:35.276Z - info: ControllerMpd::parseState
2019-03-20T08:14:35.300Z - info: ControllerMpd::sendMpdCommand playlistinfo
2019-03-20T08:14:35.338Z - info: sending command...
2019-03-20T08:14:35.403Z - info: this.currentSongDuration:210000 - this.currentSeek:208941 - remainingTime:1059 - this.askedForPrefetch:true
2019-03-20T08:14:35.446Z - info: parsing response...
2019-03-20T08:14:35.481Z - info: ControllerMpd::parseTrackInfo
2019-03-20T08:14:35.517Z - info: ControllerMpd::pushState
2019-03-20T08:14:35.541Z - info: CoreCommandRouter::servicePushState
2019-03-20T08:14:35.543Z - info: CoreStateMachine::syncState
2019-03-20T08:14:35.545Z - info: CorePlayQueue::getTrack 5
2019-03-20T08:14:35.571Z - info: STATE SERVICE {"status":"play","position":0,"seek":394,"duration":234,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"Mystère","artist":"Nolwenn Leroy","album":"Histoires naturelles","uri":"NAS/Music-flac/Music Pop Rock Library/...","trackType":"flac"}
2019-03-20T08:14:35.574Z - info: CURRENT POSITION 5
2019-03-20T08:14:35.617Z - info: CoreStateMachine::syncState   stateService play
2019-03-20T08:14:35.623Z - info: CoreStateMachine::syncState   currentStatus play
2019-03-20T08:14:35.625Z - info: Received an update from plugin. extracting info from payload
2019-03-20T08:14:35.664Z - info: CoreStateMachine::pushState
2019-03-20T08:14:35.682Z - info: CoreStateMachine::getState
2019-03-20T08:14:35.684Z - info: CorePlayQueue::getTrack 5
2019-03-20T08:14:35.702Z - info: CoreCommandRouter::volumioPushState
2019-03-20T08:14:35.704Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-03-20T08:14:36.128Z - info: CoreStateMachine::pushState
2019-03-20T08:14:36.145Z - info: CoreStateMachine::getState
2019-03-20T08:14:36.176Z - info: CorePlayQueue::getTrack 5
2019-03-20T08:14:36.186Z - info: CoreCommandRouter::volumioPushState
2019-03-20T08:14:36.227Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-03-20T08:14:37.010Z - info: ------------------------------ 2013ms
2019-03-20T08:14:37.196Z - info: this.currentSongDuration:210000 - this.currentSeek:210753 - remainingTime:-753 - this.askedForPrefetch:true
2019-03-20T08:14:37.577Z - info: this.currentSongDuration:210000 - this.currentSeek:211137 - remainingTime:-1137 - this.askedForPrefetch:true
2019-03-20T08:14:37.867Z - info: this.currentSongDuration:210000 - this.currentSeek:211413 - remainingTime:-1413 - this.askedForPrefetch:true
2019-03-20T08:14:38.123Z - info: this.currentSongDuration:210000 - this.currentSeek:211687 - remainingTime:-1687 - this.askedForPrefetch:true

I will now investigating where the info is processed: “2019-03-20T08:14:35.625Z - info: Received an update from plugin. extracting info from payload”

I have tested the following bugfix: https://github.com/volumio/Volumio2/compare/master…michaelpeeters:bugfix-playlist-stops

Not sure if this is a clean / correct solution, respecting the “statemachine.js” philosophy. Anyway, in my test, the queue gets played fine.

Any feedback is welcome, before I submit a PR:

to test it

cd /volumio/app
mv statemachine.js statemachine.orig
wget https://github.com/michaelpeeters/Volumio2/raw/bugfix-playlist-stops/app/statemachine.js
chmod +x statemachine.js
sudo reboot

To undo mv statemachine.orig statemachine.js .

This is not a solution for random playback of the songs of the queue.

I did a lot of tests with sequential / random playlists of local songs (using the mpd engine) and finally ended with the same solution as detailed in https://volumio.org/forum/possible-bug-statemachine-increaseplaybacktimer-t11921.html.

I’ve updated my fix accordingly: https://github.com/volumio/Volumio2/compare/master…michaelpeeters:bugfix-playlist-stops

If you want to try it, ssh to your volumio device and execute the following commands:

cd /volumio/app
mv statemachine.js statemachine.orig
wget https://github.com/michaelpeeters/Volumio2/raw/bugfix-playlist-stops/app/statemachine.js
chmod +x statemachine.js
sudo reboot

To undo mv statemachine.orig statemachine.js
This hotfix reverses the following patch from 2018-07-24, but in my case the cure is worse than the solution:

I’ll test this further. Any feedback is more than welcome :slight_smile:.

Thanks a lot for looking in to this issue. It was really causing me problems. I spent months trying different settings and swapping DACs and Wifi dongles before I realized it was a software bug. Since its not being widely reported it must only be effecting a small number of devices but the bug was so bad on my RPiB+ it was happening every time I used it, I was about to give up on Volumio but I stumbled on a fix. Since then Volumio has been rock solid. The original fix from last summer was apparently related to plugins and I’m not using any so Ive had no problems.

The symptoms of this problem seem to be the playback queue stops after a random number of tracks. If you look in the /var/log/volumio.log file you can see that volumio keeps sending tracks to MPD at time intervals that correspond to the track length. But it is apparently ‘unaware’ that MPD has stopped. Also you notice that the line ‘info: CoreStateMachine::stPlaybackTimer’ does not appear in the log after the last track that plays correctly.

Hi, new install of volumio I’m also getting playback stopping after 2 tracks, connection speed is fine and it plays if I click play again so not sure what the cause is

OK, I think I found a solution (or workaround?) for both the issue where playlists suddenly stop playing AND for the mismatch between the volumio web ui and the songs playing.

The fix addresses 2 issues:

I’ve again updated my fix: https://github.com/volumio/Volumio2/compare/master…michaelpeeters:bugfix-playlist-stops.

If you want to try it, ssh to your volumio device and execute the following commands:

cd /volumio/app
mv statemachine.js statemachine.orig
wget https://github.com/michaelpeeters/Volumio2/raw/bugfix-playlist-stops/app/statemachine.js
chmod +x statemachine.js
sudo reboot

To undo mv statemachine.orig statemachine.js

I tested this fix for a few days now, and until now my volumio seems to be fully operational again, both in sequential en random playback. Please note that I only use local media from my NAS, internally this is served by MPD.

In the logs I see that my fix is triggered and does seem to be effective:

$ sudo journalctl -f | grep "ERROR" Mar 29 09:13:21 volumio-pi-living volumio[769]: info: ERROR increasePlaybackTimer remainingTime:-4802 negative - askedForPrefetch:true - simulateStopStartDone:false Mar 29 09:16:28 volumio-pi-living volumio[769]: info: ERROR Prefetch 500ms setTimeout missed >> directly calling increasePlaybackTimer Mar 29 09:16:28 volumio-pi-living volumio[769]: info: ERROR this.runPlaybackTimer:true this.currentSongDuration:191000 - this.currentSeek:190373 - this.prefetchDone:true - this.simulateStopStartDone:false Mar 29 09:16:28 volumio-pi-living volumio[769]: info: ERROR increasePlaybackTimer remainingTime:-374 negative - askedForPrefetch:true - simulateStopStartDone:false Mar 29 09:43:28 volumio-pi-living volumio[769]: info: ERROR Prefetch 500ms setTimeout missed >> directly calling increasePlaybackTimer Mar 29 09:43:28 volumio-pi-living volumio[769]: info: ERROR this.runPlaybackTimer:true this.currentSongDuration:230000 - this.currentSeek:229435 - this.prefetchDone:true - this.simulateStopStartDone:false Mar 29 09:43:28 volumio-pi-living volumio[769]: info: ERROR increasePlaybackTimer remainingTime:-321 negative - askedForPrefetch:true - simulateStopStartDone:false Mar 29 10:03:15 volumio-pi-living volumio[769]: info: ERROR Prefetch 500ms setTimeout missed >> directly calling increasePlaybackTimer Mar 29 10:03:15 volumio-pi-living volumio[769]: info: ERROR this.runPlaybackTimer:true this.currentSongDuration:321000 - this.currentSeek:320381 - this.prefetchDone:true - this.simulateStopStartDone:false Mar 29 10:03:15 volumio-pi-living volumio[769]: info: ERROR increasePlaybackTimer remainingTime:-243 negative - askedForPrefetch:true - simulateStopStartDone:false

Any feedback is more than welcome :slight_smile:. Big thanks to the volumio project!

Tried your fix and so far fingers crossed it seems to be working a treat, been able to play entire albums worth of play lists without vumio stopping and the interface always reports the correct track that is playing, will continue to test but so far seems like it’s fixed, big thanks

Nice work so far. I opened an issue for this github.com/volumio/Volumio2/issues/1745.

Does anyone know if a fix has been rolled into vers 2.575?

This has been bugging me since I first installed Volumio (on a RPI0 with Justboom phat amp). Not getting a full albums playback in one hit is almost a deal breaker and the random nature of the fault means my better half is completely turned off by the whole system. I love the sound quality I get out of my set up and was considering a MyVolumio subscription but until this bug is fixed I am holding off.

I totally missed this conversation… Blame on me.
Could you please open a Pull request so I can test it and eventually merge it? Many thanks!

I just posted a pullrequest: github.com/volumio/Volumio2/pull/1753

after a few weeks, the fix seems to be OK in my case, both for random and sequential playback, even with relatively long queues.

Please note that I only use local media, so I cannot guarantee that all other use cases are working (e.g. streaming).

Again, thanks for the excellent project :slight_smile: