Just updated to 2.114 on my Pi 3 with HiFiberry DAC. I am now getting a random pause at the end of songs. It doesn’t happen after every song and I can’t seem to identify a patter that triggers the event but it happens frequently enough to be very annoying. Pushing play starts things back up and works OK until the next random event. I use the GPIO plugin as well as the Web interface. I also use the random play selection. I have countless hours using this same configuration under ver 2.041 and have never experienced this situation. The only change in my usage habits has been the update to 2.114.
I think the problem revolves around the “random” play feature. I used playback in normal mode for several hours with no problems. Three songs after switching to “Random” mode the playback stopped.
Hi calvin,
I experienced the same thing today.
In the logs, I found the message: “Stopping playback through UPNP” even though I did not actively control anything.
When it happened, Volumio was in hotspot mode and only my Android tablet was connected. I’m not aware of any UPNP app being active though…
Maybe its the same bug. Can you verify by executing “sudo journalctl -f” and waiting for the bug to occur?
The full log is here:
The Placebo song played fine (although I’m not sure whether it completed) and then playback stopped.
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::servicePushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269540] CoreStateMachine::syncState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269541] CorePlayQueue::getTrack 285
Mar 05 15:31:09 volumio volumio[1153]: 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 05 15:31:09 volumio volumio[1153]: info: CURRENT POSITION 285
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269543] CoreStateMachine::syncState stateService stop
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269544] CoreStateMachine::syncState currentStatus play
Mar 05 15:31:09 volumio volumio[1153]: info: CURRENT POSITION 285
Mar 05 15:31:09 volumio volumio[1153]: RANDOM: true OBJ {"uri":"mnt/INTERNAL/Placebo - A Place For Us To Dream/CD1/(03) Placebo - Come Home.mp3","service":"mpd","name":"Come Home","artist":"Placebo","album":"A Place For Us To Dream","type":"track","tracknumber":0,"albumart":"/albumart?web=Placebo/A%20Place%20For%20Us%20To%20Dream/extralarge&path=%2FINTERNAL%2FPlacebo%20-%20A%20Place%20For%20Us%20To%20Dream%2FCD1","duration":238,"samplerate":"44.1 KHz","bitdepth":"24 bit","trackType":"mp3","channels":2}
Mar 05 15:31:09 volumio volumio[1153]: info: CURRENT POSITION 151
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269548] CoreStateMachine::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269548] CoreStateMachine::getState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269549] CorePlayQueue::getTrack 151
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::volumioPushState
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfoMar 05 15:31:09 volumio volumio[1153]: info: [1488724269552] interfaceApi::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269554] InterfaceWebUI::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: Prefetch done, skipping queuing
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269591] CoreStateMachine::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269592] CoreStateMachine::getState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269593] CorePlayQueue::getTrack 151
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::volumioPushState
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfoMar 05 15:31:09 volumio volumio[1153]: info: [1488724269598] interfaceApi::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269599] InterfaceWebUI::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269647] ControllerMpd::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::servicePushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269648] CoreStateMachine::syncState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269649] CorePlayQueue::getTrack 151
Mar 05 15:31:09 volumio volumio[1153]: 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 05 15:31:09 volumio volumio[1153]: info: CURRENT POSITION 151
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269659] CoreStateMachine::syncState stateService stop
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269660] CoreStateMachine::syncState currentStatus stop
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269661] CoreStateMachine::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269661] CoreStateMachine::getState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269662] CorePlayQueue::getTrack 151
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::volumioPushState
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfoMar 05 15:31:09 volumio volumio[1153]: info: [1488724269664] interfaceApi::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269665] InterfaceWebUI::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269696] No code
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269697] CoreStateMachine::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269698] CoreStateMachine::getState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269698] CorePlayQueue::getTrack 151
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::volumioPushState
Mar 05 15:31:09 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfoMar 05 15:31:09 volumio volumio[1153]: info: [1488724269710] interfaceApi::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269711] InterfaceWebUI::pushState
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269740] ------------------------------ 248ms
Mar 05 15:31:09 volumio volumio[1153]: info: [1488724269747] ------------------------------ 252ms
Mar 05 15:31:09 volumio volumio[1153]: info: Pushing Favourites {"service":"mpd","uri":"mnt/INTERNAL/Jack Garratt - Phase/(05) Jack Garratt - Worry.mp3","favourite":false}
Mar 05 15:31:09 volumio volumio[1153]: info: Pushing Favourites {"service":"mpd","uri":"mnt/INTERNAL/Jack Garratt - Phase/(05) Jack Garratt - Worry.mp3","favourite":false}
Mar 05 15:31:09 volumio volumio[1153]: info: Pushing Favourites {"service":"mpd","uri":"mnt/INTERNAL/Jack Garratt - Phase/(05) Jack Garratt - Worry.mp3","favourite":false}
Mar 05 15:31:09 volumio volumio[1153]: info: Pushing Favourites {"service":"mpd","uri":"mnt/INTERNAL/Jack Garratt - Phase/(05) Jack Garratt - Worry.mp3","favourite":false}
Mar 05 15:31:11 volumio volumio[1153]: info: CALLMETHOD: audio_interface upnp stopUpnpPlayback [object Object]
Mar 05 15:31:11 volumio volumio[1153]: info: CoreCommandRouter::executeOnPlugin: upnp , stopUpnpPlayback
Mar 05 15:31:11 volumio volumio[1153]: info: Stopping playback through UPNP
Mar 05 15:31:11 volumio volumio[1153]: info: [1488724271293] CoreStateMachine::setConsumeUpdateService undefined
Mar 05 15:31:12 volumio volumio[534]: :2:src/mpdcli.cxx:146::song = mpd_run_get_queue_song_pos(M_CONN, (unsigned int)pos) failed: Bad song index
Mar 05 15:31:12 volumio volumio[534]: :2:src/mpdcli.cxx:149::song = mpd_run_get_queue_song_pos(M_CONN, (unsigned int)pos) server error: 2
Mar 05 15:31:13 volumio mpd[605]: client: [597] opened from ::ffff:127.0.0.1:45876
Mar 05 15:31:13 volumio mpd[605]: client: [377] closed
Mar 05 15:31:51 volumio hotspot[1143]: +rtl871x_send_eapol
Mar 05 15:31:51 volumio hotspot[1143]: +rtl871x_send_eapol
After I saw the Bug report I switched back over to 2.041, which works great as far as this issue is concerned.
OK, here’s my “sudo journalctl -f” output when the player stops in Random mode:
Mar 06 11:07:48 volumio mpd[493]: player: played "NAS/SYNOLOGY_DS1512/Cara Dillon/Cara Dillon/11 I Am a Youth Thats Inclined to Ramble.flac"
Mar 06 11:07:48 volumio volumio[1082]: info:
Mar 06 11:07:48 volumio volumio[1082]: [1488798468507] ---------------------------- MPD announces system state update
Mar 06 11:07:48 volumio volumio[1082]: info: Mpd Status Update: playlist
Mar 06 11:07:48 volumio volumio[1082]: info:
Mar 06 11:07:48 volumio volumio[1082]: [1488798468516] ---------------------------- MPD announces state update
Mar 06 11:07:48 volumio volumio[1082]: info: Mpd Status Update: player
Mar 06 11:07:48 volumio volumio[1082]: info:
Mar 06 11:07:48 volumio volumio[1082]: [1488798468518] ---------------------------- MPD announces state update
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468523] ControllerMpd::getState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468524] ControllerMpd::sendMpdCommand status
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468528] ControllerMpd::getState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468530] ControllerMpd::sendMpdCommand status
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468532] sending command...
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468537] sending command...
Mar 06 11:07:48 volumio volumio[1082]: info:
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468560] ------------------------------ 53ms
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468562] parsing response...
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468564] parsing response...
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468567] ControllerMpd::parseState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468571] ControllerMpd::parseState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468574] ControllerMpd::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: CoreCommandRouter::servicePushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468578] CoreStateMachine::syncState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468579] CorePlayQueue::getTrack 11
Mar 06 11:07:48 volumio volumio[1082]: 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 06 11:07:48 volumio volumio[1082]: info: CURRENT POSITION 11
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468609] CoreStateMachine::syncState stateService stop
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468610] CoreStateMachine::syncState currentStatus play
Mar 06 11:07:48 volumio volumio[1082]: info: CURRENT POSITION 11
Mar 06 11:07:48 volumio volumio[1082]: RANDOM: true OBJ undefined
Mar 06 11:07:48 volumio volumio[1082]: info: CURRENT POSITION 11
Mar 06 11:07:48 volumio volumio[1082]: info: END OF QUEUE
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468622] CoreStateMachine::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: CoreCommandRouter::volumioPushState
Mar 06 11:07:48 volumio volumio[1082]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468635] interfaceApi::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468637] InterfaceWebUI::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468673] CoreStateMachine::stPlaybackTimer
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468676] ControllerMpd::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: CoreCommandRouter::servicePushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468679] CoreStateMachine::syncState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468680] CorePlayQueue::getTrack 0
Mar 06 11:07:48 volumio volumio[1082]: 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 06 11:07:48 volumio volumio[1082]: info: CURRENT POSITION 0
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468687] CoreStateMachine::syncState stateService stop
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468688] CoreStateMachine::syncState currentStatus stop
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468691] CoreStateMachine::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468693] CoreStateMachine::getState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468695] CorePlayQueue::getTrack 0
Mar 06 11:07:48 volumio volumio[1082]: info: CoreCommandRouter::volumioPushState
Mar 06 11:07:48 volumio volumio[1082]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468700] interfaceApi::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468702] InterfaceWebUI::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468731] No code
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468732] CoreStateMachine::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468734] CoreStateMachine::getState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468735] CorePlayQueue::getTrack 0
Mar 06 11:07:48 volumio volumio[1082]: info: CoreCommandRouter::volumioPushState
Mar 06 11:07:48 volumio volumio[1082]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468740] interfaceApi::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468741] InterfaceWebUI::pushState
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468803] ------------------------------ 289ms
Mar 06 11:07:48 volumio volumio[1082]: info: [1488798468809] ------------------------------ 292ms
Mar 06 11:07:48 volumio volumio[1082]: info: Pushing Favourites {"service":"mpd","uri":"","favourite":false}
Mar 06 11:07:48 volumio volumio[1082]: info: Pushing Favourites {"service":"mpd","uri":"music-library/NAS/SYNOLOGY_DS1512/Cara Dillon/Cara Dillon/01 Black Is the Colour.flac","favourite":false}
Mar 06 11:07:48 volumio volumio[1082]: info: Pushing Favourites {"service":"mpd","uri":"music-library/NAS/SYNOLOGY_DS1512/Cara Dillon/Cara Dillon/01 Black Is the Colour.flac","favourite":false}
Mar 06 11:07:51 volumio volumio[1082]: info: CALLMETHOD: audio_interface upnp stopUpnpPlayback [object Object]
Mar 06 11:07:51 volumio volumio[1082]: info: CoreCommandRouter::executeOnPlugin: upnp , stopUpnpPlayback
Mar 06 11:07:51 volumio volumio[1082]: info: Stopping playback through UPNP
Mar 06 11:07:51 volumio volumio[1082]: info: [1488798471069] CoreStateMachine::setConsumeUpdateService undefined
Mar 06 11:07:52 volumio volumio[449]: :2:src/mpdcli.cxx:146::song = mpd_run_get_queue_song_pos(M_CONN, (unsigned int)pos) failed: Bad song index
Mar 06 11:07:52 volumio volumio[449]: :2:src/mpdcli.cxx:149::song = mpd_run_get_queue_song_pos(M_CONN, (unsigned int)pos) server error: 2
Mar 06 11:07:53 volumio mpd[493]: client: [3] closed
Mar 06 11:07:53 volumio mpd[493]: client: [4] opened from ::ffff:127.0.0.1:48006
Don’t bother trying ver 2.118 recently issued. It doesn’t address the problem.
It actually has other issues resolved, but your choice 
As to the random issue, I will try to reproduce this on an odroid c1 as I saw this before.
Thanks. I didn’t mean to come off sounding nasty - just disappointed that the issue had not been solved when I saw the new release and knew the people in this thread were interested in this feature. I’ve had to revert back to using 2.041 until this problem is fixed. The only way I use Volumio is in Random mode so any other method is really of no use to me. I have a 30K+ music collection and just let the player arbitrarily pick what I listen to. I turn it on when I get up in the morning and turn it off when I go to bed.
I’m seeing the same problem with 2.389. The DAC is a HiFiBerry Digi+; I wonder if the issue is specific to that DAC. It’s not really a DAC I guess. It just feeds the bits unaltered to the SPDIF optical port.
I’m seeing this problem with a 2.389 on a Pi3 without DAC (Output via HDMI), so it’s not the DAC…