Some web radio stations no longer play, no error messages

syc · September 9, 2020, 7:26pm

I play web radio constantly on Volumio and for no apparent reason, the local NPR stations, KQED and KALW no longer produce any sound when I play them. Other radio stations play fine, and on another Volumio streamer in the house, running the same release of Volumio (albeit on an ASUS Tinkerboard S instead of a RPi 3B+) the radio stations play perfectly. I’ve tried explicitly giving it the URL for the station to see if it plays that way, but the output is still silent. The Volumio screen shows the banner for the site with “KQED Pledge-Free Stream”, and displays 32 Kbps, but no actual sound.
Looking in the mpd.log it says "player: played “https://streams.kqed.org/kqedradio” but no error messages. When I use curl from the command line on the player, there is definitely a binary stream of content coming through, and there’s no SSL certificate validation issues showing up from curl.
The only way I can get Volumio to play the KQED stream is to connect to it from my laptop and then airplay it to the Volumio streamer - which is silly when Volumio could just pul the stream directly.

Any ideas what could be causing this?

syc · September 23, 2020, 3:05pm

Has anyone else seen this problem? These stations still produce no sound and there’s not error message to be seen.

Any suggestions?

andrewnorth · September 23, 2020, 5:42pm

I’ve had the same issue, from doing some research it appears there’s a number of standards, also there’s the radio stations not obeying the standard anyway, so some stations work some of the time and not others.

I just don’t use them anymore, their loss

syc · September 23, 2020, 9:15pm

I don’t think it is a standards issue, because the stations played perfectly fine until they didn’t. And on another Volumio player in the house, using the same revision of Volumio, just a different player, the stations still work perfectly.

This is clearly a Volumio bug, so far as I can tell.

ashthespy · September 24, 2020, 10:36am

Have you tried looking at the journalctl log for any abnormalities while playing the stream?

syc · October 9, 2020, 10:20pm

That’s a great idea, I just tried it. There are a couple of errors that show up, but it looks like there’s just some null fields somewhere in the data being parsed. Things seems to just trundle along despite the errors. Here’s the error message, along with some of the context around them:

Oct 09 15:05:59 volume2 volumio[1021]: info:
Oct 09 15:05:59 volume2 volumio[1021]: ---------------------------- MPD announces system playlist update
Oct 09 15:05:59 volume2 volumio[1021]: info: Ignoring MPD Status Update
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand load "https://streams.kqed.org/kqedradio.m3u"
Oct 09 15:05:59 volume2 volumio[1021]: error: updateQueue error: null
Oct 09 15:05:59 volume2 volumio[1021]: info: ------------------------------ 3ms

But things keep chugging along as if the error were irrelevant. And I notice that when I play other stations, a similar error message comes up and they play fine.

Here’s the full log output from selecting KQED via the web app.

Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioReplaceandPlayItems
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::ClearQueue
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::stop
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::setConsumeUpdateService undefined
Oct 09 15:05:59 volume2 volumio[1021]: UNSET VOLATILE
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::stPlaybackTimer
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::updateTrackBlock
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrackBlock
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::serviceStop
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::serviceStop
Oct 09 15:05:59 volume2 volumio[1021]: info: [1602281159115] ControllerWebradio::stop
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand stop
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::clearPlayQueue
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::saveQueue
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushQueue
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::addQueueItems
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::addQueueItems
Oct 09 15:05:59 volume2 volumio[1021]: info: Adding Item to queue: http://opml.radiotime.com/Tune.ashx?id=s34804
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri
Oct 09 15:05:59 volume2 volumio[1021]: info:
Oct 09 15:05:59 volume2 volumio[1021]: ---------------------------- MPD announces state update: player
Oct 09 15:05:59 volume2 volumio[1021]: info: ControllerMpd::getState
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand status
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::parseState
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::parseTrackInfo
Oct 09 15:05:59 volume2 volumio[1021]: info: ControllerMpd::pushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::servicePushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:05:59 volume2 volumio[1021]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"kqedradio","artist":"KQED Public Radio","album":null,"uri":"https://streams.kqed.org/kqedradio","trackType":""}
Oct 09 15:05:59 volume2 volumio[1021]: verbose: CURRENT POSITION 0
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::syncState   stateService stop
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::syncState   currentStatus stop
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:05:59 volume2 volumio[1021]: info: No code
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:05:59 volume2 volumio[1021]: info: ------------------------------ 42ms
Oct 09 15:05:59 volume2 volumio[1021]: info: touch_display: Setting screensaver timeout to 120 seconds.
Oct 09 15:05:59 volume2 volumio[1021]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0
Oct 09 15:05:59 volume2 volumio[1021]: info: touch_display: Setting screensaver timeout to 120 seconds.
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::saveQueue
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushQueue
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::updateTrackBlock
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrackBlock
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreCommandRouter::volumioPlay
Oct 09 15:05:59 volume2 volumio[1021]: UNSET VOLATILE
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::play index 0
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::setConsumeUpdateService undefined
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::stop
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::setConsumeUpdateService undefined
Oct 09 15:05:59 volume2 volumio[1021]: UNSET VOLATILE
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::play index undefined
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::setConsumeUpdateService undefined
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:05:59 volume2 volumio[1021]: info: CoreStateMachine::startPlaybackTimer
Oct 09 15:05:59 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:05:59 volume2 volumio[1021]: info: [1602281159386] ControllerWebradio::clearAddPlayTrack
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand stop
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand clear
Oct 09 15:05:59 volume2 volumio[1021]: info:
Oct 09 15:05:59 volume2 volumio[1021]: ---------------------------- MPD announces system playlist update
Oct 09 15:05:59 volume2 volumio[1021]: info: Ignoring MPD Status Update
Oct 09 15:05:59 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand load "https://streams.kqed.org/kqedradio.m3u"
Oct 09 15:05:59 volume2 volumio[1021]: error: updateQueue error: null
Oct 09 15:05:59 volume2 volumio[1021]: info: ------------------------------ 3ms
Oct 09 15:06:00 volume2 volumio[1021]: info:
Oct 09 15:06:00 volume2 volumio[1021]: ---------------------------- MPD announces system playlist update
Oct 09 15:06:00 volume2 volumio[1021]: info: Ignoring MPD Status Update
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::setConsumeUpdateService mpd
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand play
Oct 09 15:06:00 volume2 volumio[1021]: info: ------------------------------ 3ms
Oct 09 15:06:00 volume2 volumio[1021]: info:
Oct 09 15:06:00 volume2 volumio[1021]: ---------------------------- MPD announces state update: player
Oct 09 15:06:00 volume2 volumio[1021]: info: ControllerMpd::getState
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand status
Oct 09 15:06:00 volume2 volumio[1021]: info:
Oct 09 15:06:00 volume2 volumio[1021]: ---------------------------- MPD announces state update: player
Oct 09 15:06:00 volume2 volumio[1021]: info: ControllerMpd::getState
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand status
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::parseState
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Oct 09 15:06:00 volume2 volumio[1021]: info:
Oct 09 15:06:00 volume2 volumio[1021]: ---------------------------- MPD announces system playlist update
Oct 09 15:06:00 volume2 volumio[1021]: info: Ignoring MPD Status Update
Oct 09 15:06:00 volume2 volumio[1021]: info: ------------------------------ 2ms
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::parseState
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::parseTrackInfo
Oct 09 15:06:00 volume2 volumio[1021]: info: ControllerMpd::pushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::servicePushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:06:00 volume2 volumio[1021]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"22.05 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"32 Kbps","isStreaming":false,"title":"kqedradio","artist":"KQED Pledge-Free Stream","album":null,"uri":"https://streams.kqed.org/kqedradio","trackType":""}
Oct 09 15:06:00 volume2 volumio[1021]: verbose: CURRENT POSITION 0
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::syncState   stateService play
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::syncState   currentStatus stop
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:06:00 volume2 volumio[1021]: info: ------------------------------ 20ms
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::parseTrackInfo
Oct 09 15:06:00 volume2 volumio[1021]: info: ControllerMpd::pushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::servicePushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:06:00 volume2 volumio[1021]: verbose: STATE SERVICE {"status":"play","position":0,"seek":417,"duration":0,"samplerate":"22.05 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"32 Kbps","isStreaming":false,"title":"kqedradio","artist":"KQED Pledge-Free Stream","album":null,"uri":"https://streams.kqed.org/kqedradio","trackType":""}
Oct 09 15:06:00 volume2 volumio[1021]: verbose: CURRENT POSITION 0
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::syncState   stateService play
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::syncState   currentStatus play
Oct 09 15:06:00 volume2 volumio[1021]: info: Received an update from plugin. extracting info from payload
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:06:00 volume2 volumio[1021]: info: ------------------------------ 56ms
Oct 09 15:06:00 volume2 volumio[1021]: info:
Oct 09 15:06:00 volume2 volumio[1021]: ---------------------------- MPD announces system playlist update
Oct 09 15:06:00 volume2 volumio[1021]: info: Ignoring MPD Status Update
Oct 09 15:06:00 volume2 volumio[1021]: info:
Oct 09 15:06:00 volume2 volumio[1021]: ---------------------------- MPD announces state update: player
Oct 09 15:06:00 volume2 volumio[1021]: info: ControllerMpd::getState
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand status
Oct 09 15:06:00 volume2 volumio[1021]: info: ------------------------------ 3ms
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::parseState
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Oct 09 15:06:00 volume2 volumio[1021]: verbose: ControllerMpd::parseTrackInfo
Oct 09 15:06:00 volume2 volumio[1021]: info: ControllerMpd::pushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::servicePushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CorePlayQueue::getTrack 0
Oct 09 15:06:00 volume2 volumio[1021]: verbose: STATE SERVICE {"status":"play","position":0,"seek":417,"duration":0,"samplerate":"22.05 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"32 Kbps","isStreaming":false,"title":"kqedradio","artist":"KQED Pledge-Free Stream","album":null,"uri":"https://streams.kqed.org/kqedradio","trackType":""}
Oct 09 15:06:00 volume2 volumio[1021]: verbose: CURRENT POSITION 0
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::syncState   stateService play
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::syncState   currentStatus play
Oct 09 15:06:00 volume2 volumio[1021]: info: Received an update from plugin. extracting info from payload
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreStateMachine::pushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::volumioPushState
Oct 09 15:06:00 volume2 volumio[1021]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Oct 09 15:06:00 volume2 volumio[1021]: info: ------------------------------ 26ms