raspi2 / xbian: mopidy not stable (crashes on pausing streams)

General
1

Hi,

I run mopidy on xbian. I run mopidy as a service, use mp3-streams (radio stations) and the gMusic-Plugin. Control is done via mpd-clients on android and ios, output is alsa on analog jack. So far, so good. Quality is fine, browsing and searching the directory, using playlists (for radio stations and gmusic-playlists) works fine.

Unfortunately, there is a catch: Mopidy is unstable. When idle, it may run for some days - but not often. Normally, it hangs every day - without any action at all. The mpd-server does not reply and only remedy is restarting the mopidy service.

What can I do to solve this problem or how could I even start to narrow down the problem?

Thanx in advance!

Matthias

2

Could you confirm what versions of everything you are running (sudo mopidyctl deps). In terms of narrowing the problem down, you could have a look through the Mopidy logs in /var/mopidy/mopidy.log for anything suspicious. You could try to disable the extensions one by one to see if any of them are responsible. You could also try to increase Mopidy’s logging, I think the simplest way is to modify level in /etc/mopidy/logging.conf; perhaps try DEBUG, wait for the issue to occur again and see what you get?

Out of interest, what version of Xbian are you running?

3

Hi,

Everything should be up to date.

Mopidy is Version 0.19.5. I only have ssh access via smartphone. This evening i will look up the other info.

4

kodi says “xbian 1.0”. The config via ssh says 20150304-2.

After mopidy is started, I can play songs. I use gmusic and mp3 streams. When I pause, the log does not look suspicious to me. the next command is also recognized, but nothing happens (no playback whatsoever, also the log stands still. the client thinks, it is still connected. The log is posted down below.

here is the log from the moment on, that the music played, then I paused. The playback stops and does not come up till the server is not reachable any more.
The next command (play) gets a reaction in the log, but does not have effect on playback.

2015-04-23 19:53:02,032 DEBUG [9768:MainThread] mopidy.audio.actor: Buffer 98% full
2015-04-23 19:53:02,135 DEBUG [9768:MainThread] mopidy.audio.actor: Buffer 100% full
2015-04-23 19:53:02,142 DEBUG [9768:MainThread] mopidy.audio.actor: Triggering event: state_changed(old_state=paused, new_state=playing, target_state=None)
2015-04-23 19:53:02,144 DEBUG [9768:MainThread] mopidy.listener: Sending state_changed to AudioListener: {‘old_state’: u’paused’, ‘target_state’: None, ‘new_state’: u’playing’}
2015-04-23 19:53:06,655 DEBUG [9768:MainThread] pykka: Registered MpdSession (urn:uuid:4f7e31f5-af5a-45c6-ac03-80413937ebfd)
2015-04-23 19:53:06,657 DEBUG [9768:MainThread] pykka: Starting MpdSession (urn:uuid:4f7e31f5-af5a-45c6-ac03-80413937ebfd)
2015-04-23 19:53:06,658 INFO [9768:MpdSession-12] mopidy.mpd.session: New MPD connection from [::ffff:172.16.172.45]:37667
2015-04-23 19:53:06,663 DEBUG [9768:MpdSession-12] mopidy.mpd.session: Request from [::ffff:172.16.172.45]:37667: pause
2015-04-23 19:53:06,667 DEBUG [9768:MpdSession-12] mopidy.mpd.session: Response to [::ffff:172.16.172.45]:37667: OK
2015-04-23 19:53:06,687 DEBUG [9768:Audio-2] mopidy.audio.actor: Setting GStreamer state to GST_STATE_PAUSED is OK
2015-04-23 19:53:06,689 DEBUG [9768:Core-6] mopidy.core.playback: Changing state: playing -> paused
2015-04-23 19:53:06,690 DEBUG [9768:Core-6] mopidy.core.playback: Triggering playback state change event
2015-04-23 19:53:06,691 DEBUG [9768:Core-6] mopidy.core.playback: Triggering track playback paused event
2015-04-23 19:53:06,696 DEBUG [9768:MainThread] mopidy.audio.actor: Triggering event: state_changed(old_state=playing, new_state=paused, target_state=None)
2015-04-23 19:53:06,697 DEBUG [9768:MainThread] mopidy.listener: Sending playback_state_changed to CoreListener: {‘old_state’: u’playing’, ‘new_state’: u’paused’}
2015-04-23 19:53:06,712 DEBUG [9768:MainThread] mopidy.listener: Sending track_playback_paused to CoreListener: {‘time_position’: 4911L, ‘tl_track’: TlTrack(tlid=0, track=Track(uri=u’http://1live.akacast.akamaistream.net/7/706/119434/v1/gnl.akacast.akamaistream.net/1live’))}
2015-04-23 19:53:06,720 DEBUG [9768:MainThread] mopidy.listener: Sending state_changed to AudioListener: {‘old_state’: u’playing’, ‘target_state’: None, ‘new_state’: u’paused’}
2015-04-23 19:53:06,813 DEBUG [9768:MpdSession-12] mopidy.mpd.session: Request from [::ffff:172.16.172.45]:37667: status
2015-04-23 19:53:06,827 DEBUG [9768:MpdSession-12] mopidy.mpd.session: Response to [::ffff:172.16.172.45]:37667:
volume: 60
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 2
xfade: 0
state: pause
song: 0
songid: 0
time: 4:0
elapsed: 4.911
bitrate: 0
OK
2015-04-23 19:53:06,834 DEBUG [9768:MpdSession-11] mopidy.mpd.session: Request from [::ffff:172.16.172.45]:60331: idle “database” “mixer” “options” “output” “player” “playlist” “sticker” "update"
2015-04-23 19:53:12,348 DEBUG [9768:MainThread] pykka: Registered MpdSession (urn:uuid:81aaa9f2-7548-4416-b229-ba174d780913)
2015-04-23 19:53:12,349 DEBUG [9768:MainThread] pykka: Starting MpdSession (urn:uuid:81aaa9f2-7548-4416-b229-ba174d780913)
2015-04-23 19:53:12,351 INFO [9768:MpdSession-13] mopidy.mpd.session: New MPD connection from [::ffff:172.16.172.45]:49355
2015-04-23 19:53:12,355 DEBUG [9768:MpdSession-13] mopidy.mpd.session: Request from [::ffff:172.16.172.45]:49355: play
2015-04-23 19:53:12,364 DEBUG [9768:Audio-2] mopidy.audio.actor: Setting GStreamer state to GST_STATE_PLAYING is OK
2015-04-23 19:53:12,367 DEBUG [9768:Core-6] mopidy.core.playback: Changing state: paused -> playing
2015-04-23 19:53:12,368 DEBUG [9768:Core-6] mopidy.core.playback: Triggering playback state change event
2015-04-23 19:53:12,369 DEBUG [9768:Core-6] mopidy.core.playback: Triggering track playback resumed event
2015-04-23 19:53:12,374 DEBUG [9768:MpdSession-13] mopidy.mpd.session: Response to [::ffff:172.16.172.45]:49355: OK
2015-04-23 19:53:12,377 DEBUG [9768:MainThread] mopidy.audio.actor: Triggering event: state_changed(old_state=paused, new_state=playing, target_state=None)
2015-04-23 19:53:12,379 DEBUG [9768:MainThread] mopidy.listener: Sending playback_state_changed to CoreListener: {‘old_state’: u’paused’, ‘new_state’: u’playing’}
2015-04-23 19:53:12,397 DEBUG [9768:MainThread] mopidy.listener: Sending track_playback_resumed to CoreListener: {‘time_position’: 4764L, ‘tl_track’: TlTrack(tlid=0, track=Track(uri=u’http://1live.akacast.akamaistream.net/7/706/119434/v1/gnl.akacast.akamaistream.net/1live’))}
2015-04-23 19:53:12,406 DEBUG [9768:MainThread] mopidy.listener: Sending state_changed to AudioListener: {‘old_state’: u’paused’, ‘target_state’: None, ‘new_state’: u’playing’}
2015-04-23 19:53:12,496 DEBUG [9768:MpdSession-13] mopidy.mpd.session: Request from [::ffff:172.16.172.45]:49355: status
2015-04-23 19:53:12,510 DEBUG [9768:MpdSession-13] mopidy.mpd.session: Response to [::ffff:172.16.172.45]:49355:
volume: 60
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 2
xfade: 0
state: play
song: 0
songid: 0
time: 4:0
elapsed: 4.861
bitrate: 0
OK
2015-04-23 19:53:12,516 DEBUG [9768:MpdSession-11] mopidy.mpd.session: Request from [::ffff:172.16.172.45]:60331: idle “database” “mixer” “options” “output” “player” “playlist” “sticker” "update"
2015-04-23 19:53:20,229 DEBUG [9768:MpdSession-10] mopidy.utils.network: Client most likely disconnected.
2015-04-23 19:53:20,232 DEBUG [9768:MpdSession-10] pykka: Unregistered MpdSession (urn:uuid:e249c54c-e8ca-4fec-916a-da49b496e5b5)
2015-04-23 19:53:20,233 DEBUG [9768:MpdSession-10] pykka: Stopped MpdSession (urn:uuid:e249c54c-e8ca-4fec-916a-da49b496e5b5)
2015-04-23 19:53:20,234 DEBUG [9768:MpdSession-13] mopidy.utils.network: Client most likely disconnected.
2015-04-23 19:53:20,234 DEBUG [9768:MpdSession-12] mopidy.utils.network: Client most likely disconnected.
2015-04-23 19:53:20,235 DEBUG [9768:MpdSession-10] mopidy.utils.network: Already stopping: Actor is shutting down.
2015-04-23 19:53:20,237 DEBUG [9768:MpdSession-13] pykka: Unregistered MpdSession (urn:uuid:81aaa9f2-7548-4416-b229-ba174d780913)
2015-04-23 19:53:20,239 DEBUG [9768:MpdSession-12] pykka: Unregistered MpdSession (urn:uuid:4f7e31f5-af5a-45c6-ac03-80413937ebfd)
2015-04-23 19:53:20,241 DEBUG [9768:MpdSession-13] pykka: Stopped MpdSession (urn:uuid:81aaa9f2-7548-4416-b229-ba174d780913)
2015-04-23 19:53:20,242 DEBUG [9768:MpdSession-12] pykka: Stopped MpdSession (urn:uuid:4f7e31f5-af5a-45c6-ac03-80413937ebfd)
2015-04-23 19:53:20,242 DEBUG [9768:MpdSession-13] mopidy.utils.network: Already stopping: Actor is shutting down.
2015-04-23 19:53:20,243 DEBUG [9768:MpdSession-12] mopidy.utils.network: Already stopping: Actor is shutting down.

When I log in from another client, I get this behaviour in a loop:

2015-04-23 19:54:56,793 DEBUG [9768:MpdSession-15] mopidy.mpd.session: Request from [::ffff:172.16.172.27]:62598: status
2015-04-23 19:54:56,806 DEBUG [9768:MpdSession-15] mopidy.mpd.session: Response to [::ffff:172.16.172.27]:62598:
volume: 60
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 2
xfade: 0
state: play
song: 0
songid: 0
time: 4:0
elapsed: 4.861
bitrate: 0
OK

the loop end with this:

2015-04-23 19:55:06,232 DEBUG [9768:MpdSession-15] mopidy.utils.network: Client most likely disconnected.
2015-04-23 19:55:06,234 DEBUG [9768:MpdSession-15] pykka: Unregistered MpdSession (urn:uuid:8881ad3f-50ee-438e-abed-78ddf87ba478)
2015-04-23 19:55:06,235 DEBUG [9768:MpdSession-15] pykka: Stopped MpdSession (urn:uuid:8881ad3f-50ee-438e-abed-78ddf87ba478)
2015-04-23 19:55:06,235 DEBUG [9768:MpdSession-15] mopidy.utils.network: Already stopping: Actor is shutting down.

When I reconnect from the fist client, this is the output:

2015-04-23 19:56:10,755 DEBUG [9768:MainThread] pykka: Registered MpdSession (urn:uuid:49fd4e49-42d5-480a-b613-2157899553b7)
2015-04-23 19:56:10,756 DEBUG [9768:MainThread] pykka: Starting MpdSession (urn:uuid:49fd4e49-42d5-480a-b613-2157899553b7)
2015-04-23 19:56:10,758 INFO [9768:MpdSession-16] mopidy.mpd.session: New MPD connection from [::ffff:172.16.172.45]:53001
2015-04-23 19:56:10,767 DEBUG [9768:MpdSession-16] mopidy.mpd.session: Request from [::ffff:172.16.172.45]:53001: playid “1”

From this moment on, no client can connect anymore. Neither one of the two, that were connected, nor any new client.

5

It’s usually easiest if you can just post the output of mopidy deps so we can see the versions of everything. But anyway, your 0.19.5 version of Mopidy is somewhat out of date. if you can update to the latest version and then if you can still reproduce it we can go from there.

6

thanx for your help here, but the update was not successful - the installation broke quite completely.

Anyway, I restarted abandoning xbian and switched to osmc. maybe I can get it to work better.