Playing "Internetradio" -> "Volumio Selection" does not work

roland68 · December 17, 2017, 7:33pm

After updating to version 2.3.44 I see the new item “Internetradio” -> “Volumio Selection”.
But start playing an item fails.
In the log-files occurs the following error:

2017-12-17T19:04:45.921Z - info:
[1513537485918] ---------------------------- Client requests Volumio play
2017-12-17T19:04:45.924Z - info: CoreCommandRouter::volumioPlay
2017-12-17T19:04:45.928Z - info: [1513537485926] CoreStateMachine::play index undefined
2017-12-17T19:04:45.930Z - info: [1513537485928] CoreStateMachine::setConsumeUpdateService undefined
2017-12-17T19:04:45.932Z - info: [1513537485931] CorePlayQueue::getTrack 0
2017-12-17T19:04:45.934Z - info: [1513537485933] CoreStateMachine::startPlaybackTimer
2017-12-17T19:04:45.936Z - info: [1513537485935] CorePlayQueue::getTrack 0
2017-12-17T19:04:45.939Z - info: [1513537485937] ControllerWebradio::clearAddPlayTrack
2017-12-17T19:04:45.940Z - info: [1513537485939] ControllerMpd::sendMpdCommand stop
2017-12-17T19:04:45.942Z - info: Error:
TypeError: Cannot read property ‘then’ of undefined
at ControllerMpd.sendMpdCommand (/volumio/app/plugins/music_service/mpd/index.js:343:3)
at ControllerWebradio.clearAddPlayTrack (/volumio/app/plugins/music_service/webradio/index.js:455:27)
at Promise._successFn (/volumio/app/statemachine.js:1069:17)
at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28)
at _combinedTickCallback (internal/process/next_tick.js:73:7)
at process._tickCallback (internal/process/next_tick.js:104:9)
2017-12-17T19:04:45.943Z - info: [1513537485942] ------------------------------ 24ms

Any help is welcome.

Best regards
Roland

volumio · December 17, 2017, 10:55pm

Hi Roland, thanks for sharing, I will take a look.
What you have now in your play queue?

arjenpdevries · December 29, 2017, 2:03pm

I have a similar problem, and the same events related to “undefined” indices occur in the log.
However, sometimes it does work;
i.e., it is difficult to diagnose (and my family members are less happy when I set out to break it to debug ).

I will include two snippets of logs, maybe you can derive the real problem from there.

When the webradio did not play:

2017-12-28T20:56:01.016Z - info: CoreCommandRouter::volumioAddQueueItems
2017-12-28T20:56:01.017Z - info: [1514494561016] CoreStateMachine::addQueueItems
2017-12-28T20:56:01.017Z - info: [1514494561017] CorePlayQueue::addQueueItems
2017-12-28T20:56:01.017Z - info: Adding Item to queue: http://icecast.omroep.nl/3fm-bb-mp3
2017-12-28T20:56:01.018Z - info: [1514494561018] CorePlayQueue::saveQueue
2017-12-28T20:56:01.021Z - info: CoreCommandRouter::volumioPushQueue
2017-12-28T20:56:01.023Z - info: [1514494561023] interfaceApi::pushQueue
2017-12-28T20:56:01.024Z - info: [1514494561024] InterfaceWebUI::pushQueue
2017-12-28T20:56:01.084Z - info: [1514494561084] CoreStateMachine::updateTrackBlock
2017-12-28T20:56:01.085Z - info: [1514494561084] CorePlayQueue::getTrackBlock
2017-12-28T20:56:01.086Z - info: CoreCommandRouter::volumioPlay
2017-12-28T20:56:01.086Z - info: [1514494561086] CoreStateMachine::play index 218
2017-12-28T20:56:01.087Z - info: [1514494561086] CoreStateMachine::setConsumeUpdateService undefined
2017-12-28T20:56:01.087Z - info: [1514494561087] CoreStateMachine::stop
2017-12-28T20:56:01.088Z - info: [1514494561087] CoreStateMachine::setConsumeUpdateService undefined
2017-12-28T20:56:01.088Z - info: [1514494561088] CoreStateMachine::play index undefined
2017-12-28T20:56:01.089Z - info: [1514494561088] CoreStateMachine::setConsumeUpdateService undefined
2017-12-28T20:56:01.089Z - info: [1514494561089] CorePlayQueue::getTrack 218
2017-12-28T20:56:01.090Z - info: [1514494561089] CoreStateMachine::startPlaybackTimer
2017-12-28T20:56:01.090Z - info: [1514494561090] CorePlayQueue::getTrack 218
2017-12-28T20:56:01.091Z - info: [1514494561090] ControllerWebradio::clearAddPlayTrack
2017-12-28T20:56:01.091Z - info: [1514494561091] ControllerMpd::sendMpdCommand stop
2017-12-28T20:56:01.093Z - info: [1514494561092] sending command...

I was trying a lot of different things to fix it and/or understand better what goes wrong, including clearing the queue and trying to play using “clear queue and play”. Unfortunately, not even rebooting the device (a rasberry pi 3) did not resolve the situation.

Playing a spotify stream during all this testing always went smoothly, however, also did not fix the problem with the webradio streams.
(Could that be because this is a plugin?)

Just before giving up, much later that night, I still issued:

sudo systemctl restart mpd

Next morning, without turning on/off the Volumio but simply just playing the web radio, it worked again:

2017-12-29T08:33:14.877Z - info: CoreCommandRouter::volumioGetState
2017-12-29T08:33:14.880Z - info: [1514536394879] CoreStateMachine::getState
2017-12-29T08:33:14.883Z - info: [1514536394881] CorePlayQueue::getTrack 3
2017-12-29T08:33:14.885Z - info: 
[1514536394883] ---------------------------- Client requests Volumio state
2017-12-29T08:33:14.891Z - info: [1514536394890] InterfaceWebUI::pushState
2017-12-29T08:33:14.919Z - info: [1514536394918] ------------------------------ 43ms
2017-12-29T08:33:15.103Z - info: 
[1514536395101] ---------------------------- Client requests Menu Items
2017-12-29T08:33:15.116Z - info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
2017-12-29T08:33:15.119Z - info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
2017-12-29T08:33:15.121Z - info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
2017-12-29T08:33:15.139Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2017-12-29T08:33:15.143Z - info: [1514536395141] Listing playlists
2017-12-29T08:33:15.146Z - info: CoreCommandRouter::volumioGetState
2017-12-29T08:33:15.147Z - info: [1514536395146] CoreStateMachine::getState
2017-12-29T08:33:15.149Z - info: [1514536395148] CorePlayQueue::getTrack 3
2017-12-29T08:33:15.150Z - info: 
[1514536395149] ---------------------------- Client requests Volumio state
2017-12-29T08:33:15.151Z - info: 
[1514536395151] ---------------------------- Client requests Menu Items
2017-12-29T08:33:15.166Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2017-12-29T08:33:15.167Z - info: [1514536395166] Listing playlists
2017-12-29T08:33:15.170Z - info: [1514536395169] InterfaceWebUI::pushState
2017-12-29T08:33:15.189Z - info: [1514536395189] ------------------------------ 45ms
2017-12-29T08:33:15.225Z - info: [1514536395225] ------------------------------ 124ms
2017-12-29T08:33:15.233Z - info: [1514536395233] ------------------------------ 82ms
2017-12-29T08:33:18.748Z - info: 
[1514536398747] ---------------------------- Client requests Volumio play
2017-12-29T08:33:18.749Z - info: CoreCommandRouter::volumioPlay
2017-12-29T08:33:18.753Z - info: [1514536398751] CoreStateMachine::play index undefined
2017-12-29T08:33:18.755Z - info: [1514536398753] CoreStateMachine::setConsumeUpdateService undefined
2017-12-29T08:33:18.757Z - info: [1514536398756] CorePlayQueue::getTrack 3
2017-12-29T08:33:18.759Z - info: [1514536398758] CoreStateMachine::startPlaybackTimer
2017-12-29T08:33:18.759Z - info: [1514536398759] CorePlayQueue::getTrack 3
2017-12-29T08:33:18.761Z - info: [1514536398760] ControllerWebradio::clearAddPlayTrack
2017-12-29T08:33:18.762Z - info: [1514536398761] ControllerMpd::sendMpdCommand stop
2017-12-29T08:33:18.770Z - info: [1514536398769] sending command...
2017-12-29T08:33:18.773Z - info: [1514536398773] ------------------------------ 26ms
2017-12-29T08:33:18.779Z - info: [1514536398779] parsing response...
2017-12-29T08:33:18.781Z - info: [1514536398781] ControllerMpd::sendMpdCommand clear
2017-12-29T08:33:18.782Z - info: [1514536398782] sending command...
2017-12-29T08:33:18.786Z - info: 
[1514536398785] ---------------------------- MPD announces system playlist update
2017-12-29T08:33:18.788Z - info: Ignoring MPD Status Update
2017-12-29T08:33:18.789Z - info: [1514536398789] parsing response...
2017-12-29T08:33:18.791Z - info: [1514536398790] ControllerMpd::sendMpdCommand load "http://icecast.omroep.nl/radio2-bb-mp3"
2017-12-29T08:33:18.793Z - info: [1514536398793] sending command...
2017-12-29T08:33:18.796Z - info: 
2017-12-29T08:33:18.798Z - info: [1514536398798] ------------------------------ 14ms
2017-12-29T08:33:21.762Z - info: [1514536401761] ControllerMpd::sendMpdCommand add "http://icecast.omroep.nl/radio2-bb-mp3"
2017-12-29T08:33:21.763Z - info: [1514536401762] sending command...
2017-12-29T08:33:21.765Z - info: [1514536401764] parsing response...
2017-12-29T08:33:21.766Z - info: [1514536401766] CoreStateMachine::setConsumeUpdateService mpd
2017-12-29T08:33:21.767Z - info: [1514536401767] ControllerMpd::sendMpdCommand play
2017-12-29T08:33:21.768Z - info: [1514536401767] sending command...
2017-12-29T08:33:21.769Z - info: 
[1514536401768] ---------------------------- MPD announces system playlist update
2017-12-29T08:33:21.770Z - info: Ignoring MPD Status Update
2017-12-29T08:33:21.777Z - info: [1514536401776] parsing response...
2017-12-29T08:33:21.778Z - info: [1514536401777] ------------------------------ 9ms
2017-12-29T08:33:22.481Z - info: 
[1514536402481] ---------------------------- MPD announces state update: player
2017-12-29T08:33:22.486Z - info: [1514536402484] ControllerMpd::getState
2017-12-29T08:33:22.487Z - info: [1514536402487] ControllerMpd::sendMpdCommand status
2017-12-29T08:33:22.488Z - info: [1514536402488] sending command...
2017-12-29T08:33:22.490Z - info: 
[1514536402489] ---------------------------- MPD announces state update: player
2017-12-29T08:33:22.496Z - info: [1514536402495] ControllerMpd::getState
2017-12-29T08:33:22.497Z - info: [1514536402496] ControllerMpd::sendMpdCommand status
2017-12-29T08:33:22.498Z - info: [1514536402498] sending command...
2017-12-29T08:33:22.500Z - info: 
[1514536402499] ---------------------------- MPD announces system playlist update
2017-12-29T08:33:22.501Z - info: Ignoring MPD Status Update
2017-12-29T08:33:22.502Z - info: [1514536402501] parsing response...
2017-12-29T08:33:22.506Z - info: [1514536402505] ControllerMpd::parseState
2017-12-29T08:33:22.507Z - info: [1514536402507] ControllerMpd::sendMpdCommand playlistinfo
2017-12-29T08:33:22.509Z - info: [1514536402508] sending command...
2017-12-29T08:33:22.512Z - info: [1514536402511] parsing response...
2017-12-29T08:33:22.512Z - info: [1514536402512] ------------------------------ 13ms
2017-12-29T08:33:22.513Z - info: [1514536402513] parsing response...
2017-12-29T08:33:22.514Z - info: [1514536402513] ControllerMpd::parseState
2017-12-29T08:33:22.515Z - info: [1514536402514] ControllerMpd::sendMpdCommand playlistinfo
2017-12-29T08:33:22.518Z - info: [1514536402517] ControllerMpd::parseTrackInfo
2017-12-29T08:33:22.520Z - info: [1514536402519] sending command...
2017-12-29T08:33:22.521Z - info: [1514536402521] ControllerMpd::pushState
2017-12-29T08:33:22.522Z - info: CoreCommandRouter::servicePushState
2017-12-29T08:33:22.528Z - info: [1514536402528] CoreStateMachine::syncState
2017-12-29T08:33:22.529Z - info: [1514536402529] CorePlayQueue::getTrack 3
2017-12-29T08:33:22.530Z - info: STATE SERVICE {"status":"play","position":0,"seek":479,"duration":0,"samplerate":"48 KHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":fals
e,"repeat":false,"isStreaming":false,"title":"Ennio Morricone - Once Upon A Time In The West","artist":"NPO Radio2","album":null,"uri":"http://icecast.omroep.nl/radio2-bb-mp3","trackType
":"nl/radio2-bb-mp3"}
2017-12-29T08:33:22.531Z - info: CURRENT POSITION 3
2017-12-29T08:33:22.532Z - info: [1514536402531] CoreStateMachine::syncState   stateService play
2017-12-29T08:33:22.532Z - info: [1514536402532] CoreStateMachine::syncState   currentStatus stop
2017-12-29T08:33:22.534Z - info: [1514536402533] CoreStateMachine::pushState
2017-12-29T08:33:22.534Z - info: [1514536402534] CoreStateMachine::getState
2017-12-29T08:33:22.537Z - info: CoreCommandRouter::volumioPushState
2017-12-29T08:33:22.537Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-12-29T08:33:22.543Z - info: [1514536402543] interfaceApi::pushState
2017-12-29T08:33:22.544Z - info: [1514536402543] InterfaceWebUI::pushState
2017-12-29T08:33:22.568Z - info: [1514536402567] ------------------------------ 87ms
2017-12-29T08:33:22.571Z - info: Pushing Favourites {"service":"mpd","favourite":false}
2017-12-29T08:33:22.574Z - info: [1514536402574] parsing response...
2017-12-29T08:33:22.575Z - info: [1514536402575] ControllerMpd::parseTrackInfo
2017-12-29T08:33:22.576Z - info: [1514536402576] ControllerMpd::pushState
2017-12-29T08:33:22.577Z - info: CoreCommandRouter::servicePushState
2017-12-29T08:33:22.577Z - info: [1514536402577] CoreStateMachine::syncState
2017-12-29T08:33:22.578Z - info: [1514536402578] CorePlayQueue::getTrack 3
2017-12-29T08:33:22.578Z - info: STATE SERVICE {"status":"play","position":0,"seek":479,"duration":0,"samplerate":"48 KHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":fals
e,"repeat":false,"isStreaming":false,"title":"Ennio Morricone - Once Upon A Time In The West","artist":"NPO Radio2","album":null,"uri":"http://icecast.omroep.nl/radio2-bb-mp3","trackType
":"nl/radio2-bb-mp3"}
2017-12-29T08:33:22.579Z - info: CURRENT POSITION 3
2017-12-29T08:33:22.579Z - info: [1514536402579] CoreStateMachine::syncState   stateService play
2017-12-29T08:33:22.579Z - info: [1514536402579] CoreStateMachine::syncState   currentStatus play
2017-12-29T08:33:22.580Z - info: [1514536402580] Received an update from plaugin. extracting info from payload
2017-12-29T08:33:22.581Z - info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt
2017-12-29T08:33:22.582Z - info: [1514536402582] CoreStateMachine::pushState
2017-12-29T08:33:22.582Z - info: [1514536402582] CoreStateMachine::getState
2017-12-29T08:33:22.583Z - info: CoreCommandRouter::volumioPushState
2017-12-29T08:33:22.584Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-12-29T08:33:22.585Z - info: [1514536402585] interfaceApi::pushState
2017-12-29T08:33:22.586Z - info: [1514536402585] InterfaceWebUI::pushState
2017-12-29T08:33:22.605Z - info: [1514536402605] CoreStateMachine::pushState
2017-12-29T08:33:22.606Z - info: [1514536402605] CoreStateMachine::getState
2017-12-29T08:33:22.606Z - info: CoreCommandRouter::volumioPushState
2017-12-29T08:33:22.607Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-12-29T08:33:22.608Z - info: [1514536402608] interfaceApi::pushState
2017-12-29T08:33:22.609Z - info: [1514536402608] InterfaceWebUI::pushState
2017-12-29T08:33:22.628Z - info: [1514536402628] ------------------------------ 139ms
2017-12-29T08:33:22.652Z - info: Pushing Favourites {"service":"webradio","uri":"http://icecast.omroep.nl/radio2-bb-mp3","favourite":false}
2017-12-29T08:33:22.656Z - info: Pushing Favourites {"service":"webradio","uri":"http://icecast.omroep.nl/radio2-bb-mp3","favourite":false}

Maybe it makes sense to you!
I am still too unfamiliar with the way all scripts and tools go together to debug this problem, unfortunately.

Thanks for a great open source music player though, using it every day!!