webradio stops, restarts several minutes latter

[elcuevero]

changed stations in webradio, initially it changed stations with no problems, then audio stopped, web interface was responsive. did a vrestart no change. after several minutes audio started on it's own. http://logs.volumio.org/volumio/LSawyti.html

[xipmix]

So this is a bit of a problem

May 25 22:03:39 volumio volumio[1026]: info: [LastFM] Error: Authentication Failed - You do not have permissions to access the service
May 25 22:03:41 volumio volumio[1026]: info: [LastFM] Error: Authentication Failed - You do not have permissions to access the service

but it gets made much worse by volumio's reaction to it (lines immediately following)

May 25 22:03:45 volumio volumio[1026]: info: Pushing Favourites {"uri":"http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1788071","favourite":false}
May 25 22:03:49 volumio volumio[1026]: error:  TypeError: Cannot read property '0' of undefined
May 25 22:03:49 volumio volumio[1026]: at /volumio/app/plugins/music_service/upnp_browser/index.js:78:52
May 25 22:03:49 volumio volumio[1026]: at /volumio/app/plugins/music_service/upnp_browser/index.js:596:21
May 25 22:03:49 volumio volumio[1026]: at Parser. (/volumio/node_modules/xml2js/lib/xml2js.js:489:18)
May 25 22:03:49 volumio volumio[1026]: at emitOne (events.js:96:13)
May 25 22:03:49 volumio volumio[1026]: at Parser.emit (events.js:188:7)
May 25 22:03:49 volumio volumio[1026]: at Object.onclosetag (/volumio/node_modules/xml2js/lib/xml2js.js:447:26)
May 25 22:03:49 volumio volumio[1026]: at emit (/volumio/node_modules/sax/lib/sax.js:640:35)
May 25 22:03:49 volumio volumio[1026]: at emitNode (/volumio/node_modules/sax/lib/sax.js:645:5)
May 25 22:03:49 volumio volumio[1026]: at closeTag (/volumio/node_modules/sax/lib/sax.js:905:7)
May 25 22:03:49 volumio volumio[1026]: at Object.write (/volumio/node_modules/sax/lib/sax.js:1452:13)
May 25 22:03:49 volumio volumio[1026]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/xml2js.js:508:31)
May 25 22:03:49 volumio volumio[1026]: at Parser.parseString (/volumio/node_modules/xml2js/lib/xml2js.js:7:59)
May 25 22:03:49 volumio volumio[1026]: at /volumio/app/plugins/music_service/upnp_browser/index.js:595:24
May 25 22:03:49 volumio volumio[1026]: at Request.handleRequestResponse [as _callback] (/volumio/node_modules/unirest/index.js:463:26)
May 25 22:03:49 volumio volumio[1026]: at Request.self.callback (/volumio/node_modules/unirest/node_modules/request/request.js:187:22)
May 25 22:03:49 volumio volumio[1026]: at emitTwo (events.js:106:13)
May 25 22:03:49 volumio volumio[1026]: at Request.emit (events.js:191:7)

This is repeated essentially forever, even when you try to change stations. Although you restarted volumio it seems the problematic station in the playlist was still there and the errors continue, all the way to the end of the log. It's not obvious when the audio restarted, but possibly when you moved onto another station. Do you recall if the station that started to play was the station you selected before the problem began, or was it a different station?

[xipmix]

Digging in the code a bit, it seems we have a problem in this if statement (reformatted for readability)

78                    if(data.root.device[0].iconList[0] != undefined &&          \
                         data.root.device[0].iconList[0].icon[0] != undefined &&  \
                         data.root.device[0].iconList[0].icon[0].url != undefined) {

It seems to be failing on the first comparison which suggests there is something unexpected in data.root.device[0], most likely there is no iconList array at all. So perhaps another test is needed, eg

                    if(data.root.device[0].iconList != undefined &&
                       Array.isArray(data.root.device[0].iconList &&
                       data.root.device[0].iconList[0] != undefined &&          
                       data.root.device[0].iconList[0].icon[0] != undefined &&  
                       data.root.device[0].iconList[0].icon[0].url != undefined) {

but this is likely not the whole story. The failing function is being called as the callback at line 596 or 599:

593            if (response.status === 200) {                                      
594                var parser = new xml2js.Parser();                               
595                parser.parseString(response.body, function(err, result) {       
596                    callback(null, result);                                     
597                });                                                             
598            } else {                                                            
599                callback('error', null);                                        
600            }                                                                   

It looks like the data being handed to the callback could be null but that doesn't explain why the lines before line 78 don't explode.

I'm not familiar with the lastfm plugin. If you disable it does the problem go away?

[elcuevero]

I removed the plugin but the issue is still present even on version 2.413

[xipmix]

Ok so lastfm is probably a red herring. Can we see a log of the problem occurring without lastfm present?

[elcuevero]

Ok, last night i switched between several stations with no problems. This morning played a station and did again go through the queue and it hanged, did a vrestart after this with no results, had to do a full restart. http://logs.volumio.org/volumio/wM9Ru8Z.html

[volumio]

I see you have a ton of getState call... which is not good at all. Do you mind uninstalling the lastfm plugin and reinstall it then send logs again? What other plugins do you have installed?

[elcuevero]

It's not currently installed, actually since a couple of months back.

[volumio]

If you want help, please reply to our questions: what other plugins do you have installed?

[elcuevero]

AutoStart Backup & Restore GPIO Buttons

[volumio]

Can you please disable autostart and GPIO buttons and retry?

[elcuevero]

uninstalled all plugins, issue appeared after several changes: http://logs.volumio.org/volumio/gEVulU2.html

[volumio]

There is still something strange... too many getStates...