Playback of m3u8 radio station fails under unclear circumstances

Prerequisites

None

Volumio Information

Volumio Version: 2.861 (latest)
Hardware: RPi 3b+
DAC: No

Steps to Reproduce

  1. Add radio station (“Web Radio” --> “My Web Radios” --> “3 dots” --> “Add Webradio”: https://stream.radiofrance.fr/fip/fip.m3u8
$ curl https://stream.radiofrance.fr/fip/fip.m3u8
#EXTM3U
#EXT-X-VERSION:3
#EXT-X-STREAM-INF:PROGRAM-ID=0,BANDWIDTH=78000,CODECS="mp4a.40.2"
fip_lofi.m3u8
#EXT-X-STREAM-INF:PROGRAM-ID=0,BANDWIDTH=160000,CODECS="mp4a.40.2"
fip_midfi.m3u8
#EXT-X-STREAM-INF:PROGRAM-ID=0,BANDWIDTH=252000,CODECS="mp4a.40.2"
fip_hifi.m3u8
  1. Play it in Volumio and notice: It picks the first stream fip_lofi.m3u8 (side comment: I would prefer "highest BANDWIDTH" instead of first entry.)
  2. Add this very stream as a new radio station: https://stream.radiofrance.fr/fip/fip_lofi.m3u8
$ curl https://stream.radiofrance.fr/fip/fip_lofi.m3u8
#EXTM3U
#EXT-X-VERSION:3
#EXT-X-MEDIA-SEQUENCE:1728004
#EXT-X-TARGETDURATION:4
#EXT-X-START:TIME-OFFSET=0
#EXTINF:4.000,
/msl4/fip/prod1transcoder2/fip_aac_lofi_4_1604416229_1728004.ts
#EXTINF:4.000,
/msl4/fip/prod1transcoder2/fip_aac_lofi_4_1604416229_1728005.ts
[...]
  1. Try to play this new but very same station: It fails.

Debug Log

https://stream.radiofrance.fr/fip/fip.m3u8

Jan 18 15:13:20 hostname volumio[1069]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri
Jan 18 15:13:21 hostname volumio[1069]: info: CoreCommandRouter::volumioReplaceandPlayItems
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::ClearQueue
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::stop
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 18 15:13:21 hostname volumio[1069]: UNSET VOLATILE
Jan 18 15:13:21 hostname volumio[1069]: info: CorePlayQueue::clearPlayQueue
Jan 18 15:13:21 hostname volumio[1069]: info: CorePlayQueue::saveQueue
Jan 18 15:13:21 hostname volumio[1069]: info: CoreCommandRouter::volumioPushState
Jan 18 15:13:21 hostname volumio[1069]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jan 18 15:13:21 hostname volumio[1069]: info: CoreCommandRouter::volumioPushQueue
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::addQueueItems
Jan 18 15:13:21 hostname volumio[1069]: info: CorePlayQueue::addQueueItems
Jan 18 15:13:21 hostname volumio[1069]: info: Adding Item to queue: https://stream.radiofrance.fr/fip/fip.m3u8
Jan 18 15:13:21 hostname volumio[1069]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri
Jan 18 15:13:21 hostname volumio[1069]: info: CorePlayQueue::saveQueue
Jan 18 15:13:21 hostname volumio[1069]: info: CoreCommandRouter::volumioPushQueue
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::updateTrackBlock
Jan 18 15:13:21 hostname volumio[1069]: info: CorePlayQueue::getTrackBlock
Jan 18 15:13:21 hostname volumio[1069]: info: CoreCommandRouter::volumioPlay
Jan 18 15:13:21 hostname volumio[1069]: UNSET VOLATILE
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::play index 0
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::stop
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 18 15:13:21 hostname volumio[1069]: UNSET VOLATILE
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::play index undefined
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 18 15:13:21 hostname volumio[1069]: info: CorePlayQueue::getTrack 0
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::startPlaybackTimer
Jan 18 15:13:21 hostname volumio[1069]: info: CorePlayQueue::getTrack 0
Jan 18 15:13:21 hostname volumio[1069]: info: [1610982801895] ControllerWebradio::clearAddPlayTrack
Jan 18 15:13:21 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand stop
Jan 18 15:13:21 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand clear
Jan 18 15:13:21 hostname volumio[1069]: info:
Jan 18 15:13:21 hostname volumio[1069]: ---------------------------- MPD announces system playlist update
Jan 18 15:13:21 hostname volumio[1069]: info: Ignoring MPD Status Update
Jan 18 15:13:21 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand load "https://stream.radiofrance.fr/fip/fip.m3u8"
Jan 18 15:13:21 hostname volumio[1069]: error: updateQueue error: null
Jan 18 15:13:21 hostname volumio[1069]: info: ------------------------------ 3ms
Jan 18 15:13:21 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService mpd
Jan 18 15:13:21 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand play
Jan 18 15:13:21 hostname volumio[1069]: info:
Jan 18 15:13:21 hostname volumio[1069]: ---------------------------- MPD announces system playlist update
Jan 18 15:13:21 hostname volumio[1069]: info: Ignoring MPD Status Update
Jan 18 15:13:21 hostname volumio[1069]: info: ------------------------------ 3ms
Jan 18 15:13:22 hostname volumio[1069]: info:
Jan 18 15:13:22 hostname volumio[1069]: ---------------------------- MPD announces state update: player
Jan 18 15:13:22 hostname volumio[1069]: info: ControllerMpd::getState
Jan 18 15:13:22 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand status
Jan 18 15:13:22 hostname volumio[1069]: info:
Jan 18 15:13:22 hostname volumio[1069]: ---------------------------- MPD announces state update: player
Jan 18 15:13:22 hostname volumio[1069]: info: ControllerMpd::getState
Jan 18 15:13:22 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand status
Jan 18 15:13:22 hostname volumio[1069]: verbose: ControllerMpd::parseState
Jan 18 15:13:22 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Jan 18 15:13:22 hostname volumio[1069]: verbose: ControllerMpd::parseState
Jan 18 15:13:22 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Jan 18 15:13:22 hostname volumio[1069]: verbose: ControllerMpd::parseTrackInfo
Jan 18 15:13:22 hostname volumio[1069]: info: ControllerMpd::pushState
Jan 18 15:13:22 hostname volumio[1069]: info: CoreCommandRouter::servicePushState
Jan 18 15:13:22 hostname volumio[1069]: info: CorePlayQueue::getTrack 0
Jan 18 15:13:22 hostname volumio[1069]: verbose: STATE SERVICE {"status":"play","position":0,"seek":480,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"34 Kbps","isStreaming":false,"title":"fip_lofi.m3u8","artist":null,"album":null,"uri":"https://stream.radiofrance.fr/fip/fip_lofi.m3u8","trackType":"m3u8"}
Jan 18 15:13:22 hostname volumio[1069]: verbose: CURRENT POSITION 0
Jan 18 15:13:22 hostname volumio[1069]: info: CoreStateMachine::syncState   stateService play
Jan 18 15:13:22 hostname volumio[1069]: info: CoreStateMachine::syncState   currentStatus stop
Jan 18 15:13:22 hostname volumio[1069]: info: CoreStateMachine::pushState
Jan 18 15:13:22 hostname volumio[1069]: info: CoreCommandRouter::volumioPushState
Jan 18 15:13:22 hostname volumio[1069]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jan 18 15:13:22 hostname volumio[1069]: info: ------------------------------ 32ms
Jan 18 15:13:22 hostname volumio[1069]: verbose: ControllerMpd::parseTrackInfo
Jan 18 15:13:22 hostname volumio[1069]: info: ControllerMpd::pushState
Jan 18 15:13:22 hostname volumio[1069]: info: CoreCommandRouter::servicePushState
Jan 18 15:13:22 hostname volumio[1069]: info: CorePlayQueue::getTrack 0
Jan 18 15:13:22 hostname volumio[1069]: verbose: STATE SERVICE {"status":"play","position":0,"seek":480,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"34 Kbps","isStreaming":false,"title":"fip_lofi.m3u8","artist":null,"album":null,"uri":"https://stream.radiofrance.fr/fip/fip_lofi.m3u8","trackType":"m3u8"}
Jan 18 15:13:22 hostname volumio[1069]: verbose: CURRENT POSITION 0
Jan 18 15:13:22 hostname volumio[1069]: info: CoreStateMachine::syncState   stateService play
Jan 18 15:13:22 hostname volumio[1069]: info: CoreStateMachine::syncState   currentStatus play
Jan 18 15:13:22 hostname volumio[1069]: info: Received an update from plugin. extracting info from payload
Jan 18 15:13:22 hostname volumio[1069]: info: CoreStateMachine::pushState
Jan 18 15:13:22 hostname volumio[1069]: info: CoreCommandRouter::volumioPushState
Jan 18 15:13:22 hostname volumio[1069]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jan 18 15:13:22 hostname volumio[1069]: info: CoreStateMachine::pushState
Jan 18 15:13:22 hostname volumio[1069]: info: CoreCommandRouter::volumioPushState
Jan 18 15:13:22 hostname volumio[1069]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jan 18 15:13:22 hostname volumio[1069]: info: ------------------------------ 53ms

https://stream.radiofrance.fr/fip/fip_lofi.m3u8

Jan 18 15:16:27 hostname volumio[1069]: info: CoreCommandRouter::volumioReplaceandPlayItems
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::ClearQueue
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::stop
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 18 15:16:27 hostname volumio[1069]: UNSET VOLATILE
Jan 18 15:16:27 hostname volumio[1069]: info: CorePlayQueue::clearPlayQueue
Jan 18 15:16:27 hostname volumio[1069]: info: CorePlayQueue::saveQueue
Jan 18 15:16:27 hostname volumio[1069]: info: CoreCommandRouter::volumioPushState
Jan 18 15:16:27 hostname volumio[1069]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Jan 18 15:16:27 hostname volumio[1069]: info: CoreCommandRouter::volumioPushQueue
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::addQueueItems
Jan 18 15:16:27 hostname volumio[1069]: info: CorePlayQueue::addQueueItems
Jan 18 15:16:27 hostname volumio[1069]: info: Adding Item to queue: https://stream.radiofrance.fr/fip/fip_lofi.m3u8
Jan 18 15:16:27 hostname volumio[1069]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri
Jan 18 15:16:27 hostname volumio[1069]: info: CorePlayQueue::saveQueue
Jan 18 15:16:27 hostname volumio[1069]: info: CoreCommandRouter::volumioPushQueue
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::updateTrackBlock
Jan 18 15:16:27 hostname volumio[1069]: info: CorePlayQueue::getTrackBlock
Jan 18 15:16:27 hostname volumio[1069]: info: CoreCommandRouter::volumioPlay
Jan 18 15:16:27 hostname volumio[1069]: UNSET VOLATILE
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::play index 0
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::stop
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 18 15:16:27 hostname volumio[1069]: UNSET VOLATILE
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::play index undefined
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService undefined
Jan 18 15:16:27 hostname volumio[1069]: info: CorePlayQueue::getTrack 0
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::startPlaybackTimer
Jan 18 15:16:27 hostname volumio[1069]: info: CorePlayQueue::getTrack 0
Jan 18 15:16:27 hostname volumio[1069]: info: [1610982987714] ControllerWebradio::clearAddPlayTrack
Jan 18 15:16:27 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand stop
Jan 18 15:16:27 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand clear
Jan 18 15:16:27 hostname volumio[1069]: info:
Jan 18 15:16:27 hostname volumio[1069]: ---------------------------- MPD announces system playlist update
Jan 18 15:16:27 hostname volumio[1069]: info: Ignoring MPD Status Update
Jan 18 15:16:27 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand load "https://stream.radiofrance.fr/fip/fip_lofi.m3u8"
Jan 18 15:16:27 hostname volumio[1069]: error: updateQueue error: null
Jan 18 15:16:27 hostname volumio[1069]: info: ------------------------------ 7ms
Jan 18 15:16:27 hostname volumio[1069]: info: CoreStateMachine::setConsumeUpdateService mpd
Jan 18 15:16:27 hostname volumio[1069]: verbose: ControllerMpd::sendMpdCommand play

Additional Information

Neither does it work with the “new” mpd version 0.21.16 from the new Youtube plugin.

1 Like

Same issue on mine on various radios running 2.861 on PI rev. 3B since 2.799

I got interesting logs at playout stop on this radio station : http://stream.srg-ssr.ch/m/couleur3/mp3_128

Jan 31 09:50:02 volumio volumio[1379]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd
Jan 31 09:50:02 volumio volumio[1379]: info: ------------------------------ 20ms
Jan 31 09:50:02 volumio cron[630]: 2021-01-31 09:50:02 1l69Mo-000052-1Y Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=114 egid=120
Jan 31 09:50:02 volumio exim[312]: 2021-01-31 09:50:02 1l69Mo-000052-1Y <= volumio@localhost U=volumio P=local S=984
Jan 31 09:50:02 volumio exim[312]: 2021-01-31 09:50:02 1l69Mo-000052-1Y Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=114 egid=120
Jan 31 09:50:02 volumio exim[312]: exim: could not open panic log - aborting: see message(s) above
Jan 31 09:50:02 volumio CRON[305]: (volumio) MAIL (mailed 365 bytes of output but got status 0x0001 from MTA
                                   )
Jan 31 09:50:02 volumio CRON[305]: pam_unix(cron:session): session closed for user volumio
Jan 31 09:50:02 volumio cron[630]: 2021-01-31 09:50:02 1l69Mo-000052-1Y <= volumio@localhost U=volumio P=local S=984
Jan 31 09:50:02 volumio cron[630]: 2021-01-31 09:50:02 1l69Mo-000052-1Y Cannot open main log file "/var/log/exim4/mainlog": Permission denied: euid=114 egid=120
Jan 31 10:17:01 volumio CRON[4198]: pam_unix(cron:session): session closed for user root

As well I generated log : http://logs.volumio.org/volumio/cCE2YhL.html

could be a “Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd”

I continue troubleshooting, keep tuned

found and solved !
the hell , who this come in the volumio user 's crontab following:
50 * * * * curl “http://localhost:3000/api/v1/commands/?cmd=stop

Since I commented this , no disconnection.

I have nothing besides

/etc/cron.daily
/etc/cron.hourly
/etc/cron.weekly

and no file in there contains a curl. So this unfortunately does not hold for me.

@smoneck, what if you check logged as volumio “crontab -e” ?

Well, as I said, I don’t have a /usr/bin/crontab. But it’s interesting that you have and I don’t.