I have a RPi Model B with hifiberry DAC installed. Running musicbox 0.5 was fine, everything worked as it should.
I have just changed to Musicbox 0.5.3. Everything works, but when I select a TuneIn radio station stream, it takes about 40 seconds to start. Playing local media is fine and starts immediately.
I’ve tried looking a the mopidy logs, but can’t see anything obvious.
Has anyone else experienced the same?
I don’t think the version of Mopidy-TuneIn changed (on account of there not
being any releases for ages). Some stations take a while to start because
there a lot of nested playlist that must be requested and expanded, can you
confirm if this is for all stations or just some. If you can run in verbose
mode then you can probably see what’s going on.
Hi
Thanks for your reply. It seems to be for all stations or podcasts. The same stations and podcasts start almost instantly on 0.5 so I’m not sure what the problem is.
This is the output from the mopidy log when I start a station:
2015-01-28 13:09:12,861 - INFO Starting new HTTP connection (1): opml.radiotime.com
2015-01-28 13:09:14,352 - INFO Starting new HTTP connection (1): bbcmedia.ic.llnwd.net
date
Wed Jan 28 13:09:50 UTC 2015
I ran date when the station started, so you can see it took quite a while to start.
I’m not sure I’m getting the right amount of logging from mopidy. I changed it to run with -vvv but the above is all I get.
I’ve managed to get a bit extra from mopidy, not sure if the D-Bus errors are an issue?
2015-01-28 13:14:32,257 - INFO Starting new HTTP connection (1): opml.radiotime.com
INFO 2015-01-28 13:14:32,257 [3297:TuneInBackend-11] requests.packages.urllib3.connectionpool
Starting new HTTP connection (1): opml.radiotime.com
2015-01-28 13:14:42,449 - INFO Starting new HTTP connection (1): opml.radiotime.com INFO 2015-01-28 13:14:42,449 [3297:TuneInBackend-11] requests.packages.urllib3.connectionpool Starting new HTTP connection (1): opml.radiotime.com
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
2015-01-28 13:14:45,492 - INFO Starting new HTTP connection (1): open.live.bbc.co.uk
INFO 2015-01-28 13:14:45,492 [3297:TuneInBackend-11] requests.packages.urllib3.connectionpool
Starting new HTTP connection (1): open.live.bbc.co.uk
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3297): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
2015-01-28 13:14:45,843 - INFO 200 GET /images/icons/play_alt_12x12.png (192.168.1.118) 16.45ms
INFO 2015-01-28 13:14:45,843 [3297:HttpServer] tornado.access
200 GET /images/icons/play_alt_12x12.png (192.168.1.118) 16.45msD-Bus errors are usually red-herrings. I can’t remember how much logging is in that version of Mopidy-Tunein but there should be some extra DEBUG stuff at least, you’re only getting INFO.
The simplest way is if you stop both the mopidy and monit services (service monit stop, service mopidy stop) and then run Mopidy with the following command it should hopefully be more enlightening.
sudo -H -u mopidy bash -c '/usr/local/bin/mopidy --config /etc/mopidy/mopidy.conf -o loglevels/mopidy_tunein=debug'
Thanks. I’ve managed to get a lot more info now. I can’t see any obvious reason for the delay, but maybe more experienced eyes will be able to spot something. I had a put an x in front of the http as it won’t let me post more than 2 links 
DEBUG 2015-01-28 13:44:55,402 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.play”,“params”:[{“track”:{“album”:{“uri”:“x”,“name”:""},“model”:“Track”,“name”:“BBC Radio 3”,“uri”:“tunein:station:s24941”},“model”:“TlTrack”,“tlid”:17}],“jsonrpc”:“2.0”,“id”:278}‘
DEBUG 2015-01-28 13:44:55,414 [3342:Core-14] mopidy.core.playback
Changing state: stopped -> playing
DEBUG 2015-01-28 13:44:55,420 [3342:Core-14] mopidy.core.playback
Triggering playback state change event
DEBUG 2015-01-28 13:44:55,427 [3342:MainThread] mopidy.listener
Sending playback_state_changed to CoreListener: {‘old_state’: u’stopped’, ‘new_state’: u’playing’}
DEBUG 2015-01-28 13:44:55,497 [3342:Audio-2] mopidy.audio.actor
Setting GStreamer state to GST_STATE_READY is OK
DEBUG 2015-01-28 13:44:55,514 [3342:TuneInBackend-11] mopidy_tunein.tunein
Tuning station id s24941
DEBUG 2015-01-28 13:44:55,520 [3342:TuneInBackend-11] mopidy_tunein.tunein
TuneIn request: xhttp://opml.radiotime.com/Tune.ashx?render=json&id=s24941
INFO 2015-01-28 13:44:55,548 [3342:TuneInBackend-11] requests.packages.urllib3.connectionpool
Starting new HTTP connection (1): opml.radiotime.com
DEBUG 2015-01-28 13:44:55,953 [3342:TuneInBackend-11] requests.packages.urllib3.connectionpool
"GET /Tune.ashx?render=json&id=s24941 HTTP/1.1" 200 275
DEBUG 2015-01-28 13:44:55,988 [3342:TuneInBackend-11] mopidy_tunein.actor
Stream URI: xhttp://bbcmedia.ic.llnwd.net/stream/bbcmedia_radio3_mf_p.m3u.
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
DEBUG 2015-01-28 13:44:57,197 [3342:TuneInBackend-11] mopidy_tunein.actor
Problem looking up xhttp://bbcmedia.ic.llnwd.net/stream/bbcmedia_radio3_mf_p.m3u: Timeout after 1000ms.
DEBUG 2015-01-28 13:44:57,203 [3342:TuneInBackend-11] mopidy_tunein.tunein
Using TuneIn extension parsing: xhttp://bbcmedia.ic.llnwd.net/stream/bbcmedia_radio3_mf_p.m3u
INFO 2015-01-28 13:44:57,235 [3342:TuneInBackend-11] requests.packages.urllib3.connectionpool
Starting new HTTP connection (1): bbcmedia.ic.llnwd.net
DEBUG 2015-01-28 13:44:57,355 [3342:TuneInBackend-11] requests.packages.urllib3.connectionpool
"GET /stream/bbcmedia_radio3_mf_p.m3u HTTP/1.1" 200 None
DEBUG 2015-01-28 13:44:57,369 [3342:TuneInBackend-11] mopidy_tunein.tunein
Content type: audio/x-mpegurl
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
** (mopidy:3342): WARNING **: Cannot autolaunch D-Bus without X11 $DISPLAY
DEBUG 2015-01-28 13:44:57,422 [3342:Audio-2] mopidy.audio.actor
Setting GStreamer state to GST_STATE_PLAYING is async
DEBUG 2015-01-28 13:44:57,430 [3342:Core-14] mopidy.core.playback
Triggering track playback started event
DEBUG 2015-01-28 13:44:57,437 [3342:MainThread] mopidy.listener
Sending track_playback_started to CoreListener: {‘tl_track’: TlTrack(tlid=17, track=Track(album={u’uri’: u’x’, u’name’: u’’}, artists=[], composers=[], name=u’BBC Radio 3’, performers=[], uri=u’tunein:station:s24941’))}
INFO 2015-01-28 13:44:57,482 [3342:HttpServer] tornado.access
200 GET /images/icons/pause_32x32.png (192.168.1.118) 23.33ms
DEBUG 2015-01-28 13:44:57,503 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_current_track”,“jsonrpc”:“2.0”,“id”:279}‘
DEBUG 2015-01-28 13:44:57,526 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:280}‘
DEBUG 2015-01-28 13:44:57,541 [3342:Audio-2] mopidy.audio.actor
Position query failed
DEBUG 2015-01-28 13:44:57,556 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:281}‘
DEBUG 2015-01-28 13:44:57,571 [3342:Audio-2] mopidy.audio.actor
Position query failed
DEBUG 2015-01-28 13:45:04,801 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_current_track”,“jsonrpc”:“2.0”,“id”:282}‘
DEBUG 2015-01-28 13:45:04,826 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:283}‘
DEBUG 2015-01-28 13:45:04,840 [3342:Audio-2] mopidy.audio.actor
Position query failed
DEBUG 2015-01-28 13:45:14,802 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_current_track”,“jsonrpc”:“2.0”,“id”:284}‘
DEBUG 2015-01-28 13:45:14,825 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:285}‘
DEBUG 2015-01-28 13:45:14,840 [3342:Audio-2] mopidy.audio.actor
Position query failed
DEBUG 2015-01-28 13:45:24,803 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_current_track”,“jsonrpc”:“2.0”,“id”:286}‘
DEBUG 2015-01-28 13:45:24,827 [3342:HttpServer] mopidy.http.handlers
Received WebSocket message from 192.168.1.118: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:287}‘
DEBUG 2015-01-28 13:45:24,841 [3342:Audio-2] mopidy.audio.actor
Position query failed
DEBUG 2015-01-28 13:45:26,804 [3342:MainThread] mopidy.audio.actor
Buffer 0% full
DEBUG 2015-01-28 13:45:27,661 [3342:MainThread] mopidy.audio.actor
Buffer 26% full
DEBUG 2015-01-28 13:45:27,676 [3342:MainThread] mopidy.audio.actor
Buffer 41% full
DEBUG 2015-01-28 13:45:27,689 [3342:MainThread] mopidy.audio.actor
Buffer 56% full
DEBUG 2015-01-28 13:45:27,699 [3342:MainThread] mopidy.audio.actor
Buffer 57% full
DEBUG 2015-01-28 13:45:27,730 [3342:MainThread] mopidy.audio.actor
Buffer 72% full
DEBUG 2015-01-28 13:45:27,749 [3342:MainThread] mopidy.audio.actor
Buffer 83% full
DEBUG 2015-01-28 13:45:27,795 [3342:MainThread] mopidy.audio.actor
Buffer 68% full
DEBUG 2015-01-28 13:45:27,810 [3342:MainThread] mopidy.audio.actor
Triggering event: state_changed(old_state=stopped, new_state=paused, target_state=playing)
DEBUG 2015-01-28 13:45:27,832 [3342:MainThread] mopidy.listener
Sending state_changed to AudioListener: {‘old_state’: u’stopped’, ‘target_state’: u’playing’, ‘new_state’: u’paused’}
DEBUG 2015-01-28 13:45:28,205 [3342:MainThread] mopidy.audio.actor
Buffer 67% full
DEBUG 2015-01-28 13:45:28,212 [3342:MainThread] mopidy.audio.actor
Buffer 57% full
DEBUG 2015-01-28 13:45:28,220 [3342:MainThread] mopidy.audio.actor
Buffer 41% full
DEBUG 2015-01-28 13:45:28,226 [3342:MainThread] mopidy.audio.actor
Buffer 26% full
DEBUG 2015-01-28 13:45:28,662 [3342:MainThread] mopidy.audio.actor
Buffer 33% full
DEBUG 2015-01-28 13:45:28,706 [3342:MainThread] mopidy.audio.actor
Buffer 46% full
DEBUG 2015-01-28 13:45:28,712 [3342:MainThread] mopidy.audio.actor
Buffer 58% full
DEBUG 2015-01-28 13:45:28,719 [3342:MainThread] mopidy.audio.actor
Buffer 59% full
DEBUG 2015-01-28 13:45:28,748 [3342:MainThread] mopidy.audio.actor
Buffer 67% full
DEBUG 2015-01-28 13:45:28,754 [3342:MainThread] mopidy.audio.actor
Buffer 80% full
DEBUG 2015-01-28 13:45:28,762 [3342:MainThread] mopidy.audio.actor
Buffer 93% full
DEBUG 2015-01-28 13:45:28,768 [3342:MainThread] mopidy.audio.actor
Buffer 97% full
DEBUG 2015-01-28 13:45:29,621 [3342:MainThread] mopidy.audio.actor
Buffer 91% full
DEBUG 2015-01-28 13:45:29,679 [3342:MainThread] mopidy.audio.actor
Buffer 100% full
DEBUG 2015-01-28 13:45:29,723 [3342:MainThread] mopidy.audio.actor
Triggering event: state_changed(old_state=paused, new_state=playing, target_state=None)
DEBUG 2015-01-28 13:45:29,741 [3342:MainThread] mopidy.listener
Sending state_changed to AudioListener: {‘old_state’: u’paused’, ‘target_state’: None, ‘new_state’: u’playing’}
You can use websites like www.dpaste.com to post long logs like that.
Mopidy-Tunein resolves the stream URI in a couple of seconds between 13:44:55 and 13:44:57 and sets the state to playing at 13:44:57,42 (Setting GStreamer state to GST_STATE_PLAYING is async). Then Mopidy appears to to waste about 30 seconds doing nothing except for trying to answer get_time_position requests from the browser, which all fail anyway. Once these stop (why?) the stream finally starts to buffer, which itself takes an entire 5 seconds to complete.
Perhaps it’s hard work for the Pi to answer all the get_time_position requests it’s getting. Perhaps it’s harder work for streams than local tracks since it’s a bit of a weird case (they are not seekable). Or perhaps it’s the way Mopidy-Tunein changes the track. I’m suspicious of get_time_position as once those requests stop (for whatever reason) things start going again.
Why this is a problem for you now in v0.5.3, I don’t know but I’m sure lots has changed. It would be interesting to stop the webclient doing all those requests, it’s not supposed to poll like that anyway (see https://github.com/woutervanwijk/Mopidy-MusicBox-Webclient/issues/40)
I think the position query messages might be a red herring. To eliminate those, I clicked to start the radio station and then closed the browser. This stopped the position query messages but there was still a 30 second pause before the playback started.
DEBUG 2015-01-28 15:31:59,304 [3342:HttpServer] mopidy.http.handlers
Closed WebSocket connection from 192.168.1.118
DEBUG 2015-01-28 15:32:30,778 [3342:MainThread] mopidy.audio.actor
Buffer 0% full
I’m happy to look at anything you might be able to suggest, but am not very familiar with the code for mopidy - sorry.
Good observation.
You could run with full debug statements (please don’t paste it all directly in the forum) and see if that reveals anything:
sudo -H -u mopidy bash -c '/usr/local/bin/mopidy --config /etc/mopidy/mopidy.conf -vvv'
I’m not seeing any extra than before with that method. I’ve also changed logging.conf for mopidy to be DEBUG.
There just seems to be a huge pause for some reason once the station has been resolved and the CoreListener has been told the playback is happening.
Do you know where to look for where the stream is actually played and buffered?
Have a look at the debugging section of the Mopidy docs. Particularly the
gst_debug=3 variable which will give you a LOT of info.
Thanks, it does give a lot of info!! Unfortunately nothing to indicate why it’s paused for 30 seconds. 
Can you list a few stations that you’re having problems with so we can compare? I just tested switching to a few station in the category TuneIn > Music > 80’s and the stations started playing within a few seconds.
I’m on the latest Pi Musicbox version and using a Hifiberry DAC+. My Pi is overclocked to 950Mhz, maybe this helps too.
It seems to be any station or podcast I try, but as examples:
BBC Radio 3
BBC Radio 4
Absolute 80’s
Calm Radio
I have tried using analog output instead of the hifiberry, but it’'s the same problem.
I don’t think overclocking would make a difference as the system works perfectly using MusicBox 0.5
Looking at top to see the CPU usage when I start a station, mopidy is using ~30% CPU as it decodes the URI etc but then goes to nothing until the stream starts playing 30 seconds later. So it looks like it’s sitting doing nothing there waiting for an event or something else to return.
Are you using wifi? Could it be some more examples of wireless adapter power saving features getting confused? Can you try wired?
Some of those stations may be accessible via dirble, can you see if you get the same issue when using that.
Do you have any other extensions enabled? Can you try disabling everything except tunein?
You could update the tunein extension to the new version (pip install --upgrade Mopidy-TuneIn). Since this pause occurs after the stream uri is handed over to Mopidy Core I doubt it’d help.
I’ve not tried the latest musicbox version yet but I will give it a go (without an overclock ) and see what happens. It’s interesting it’s not observable by @darkhelmet.
I’ve tried several stations via dirble but experience the same problem.
I upgraded TuneIn but that doesn’t work at all. It seems to timeout on the call to the stream URL. If I do a wget on that URL however, it connects no problem. Log extract as follows:
2015-01-29 11:28:14,020 - INFO Starting new HTTP connection (1): sc41.frf.llnw.net
2015-01-29 11:28:19,270 - INFO TuneIn playlist request for http://sc41.frf.llnw.net:80/stream/bbcmedia_radio3_mf_p failed HTTPConnectionPool(host='sc41.frf.llnw.net', port=80): Read timed out. (read timeout=5.0)
This then seems to loop through all the different radio stations, experiencing the timeout problem on each one.
I will try to set the system up wired, but I don’t think that is the problem as it works well on 0.5 with the wifi.
The wireless stuff is always changing between versions so it’s worth a
test.
Try a larger value for the timeout, say… 40 seconds maybe?! That new
version of Mopidy-TuneIn uses the configured timeout value when trying to
connect to the stream (previously it used something else .
After refreshing my memory it seems the timeout is not the issue. if you can provide the full debug log that would help.
Full debug log can be found at:
To get here I did a search in the webclient. I changed the service to TuneIn and searched for BBC Radio 3. I then clicked BBC Radio 3.