MPC inevitably times out then fails to connect permanently until restart

General
1

I have mopidy running on a Pi, playing Spotify playlists in response to external input. When I select a playlist I issue these commands:

mpc -q clear
mpc -q add spotify:...
mpc -q play

While stress testing the system, I run the above commands, waiting for each to finish, every 2 seconds and let it go for a while.

It starts off working perfectly with no issues at all. Inevitably, after about 450-500 iterations (about a half an hour), the following happens:

  • First, the “add” command starts failing. It prints “error: Timeout” after a delay and returns 1. “clear” and “play” still succeed.
  • After that happens 10 times, all three commands start failing. They print “error: Connection closed by the server” and return 1.
  • At this point it is permanently broken. service mopidy stop hangs. The only way to make it work again is killall -s 9 mopidy ; service mopidy restart.

This happens in 100% of tests. It is consistent. The system is meant to run continuously, so this is a problem.

None of the logs seem to show anything useful. At the time it fails (lines marked with # are comments added by me for this post, not present in logs):

/var/log/mopidy/mopidy.log:

# lots of these while everything is working:
2016-11-06 02:07:01,514 INFO [6052:MpdSession-741] mopidy.mpd.session: New MPD connection from [::1]:46036
2016-11-06 02:07:33,579 INFO [6052:MpdSession-742] mopidy.mpd.session: New MPD connection from [::1]:46038
2016-11-06 02:07:33,610 INFO [6052:MpdSession-743] mopidy.mpd.session: New MPD connection from [::1]:46040
2016-11-06 02:08:03,672 INFO [6052:MpdSession-744] mopidy.mpd.session: New MPD connection from [::1]:46042
2016-11-06 02:08:35,734 INFO [6052:MpdSession-745] mopidy.mpd.session: New MPD connection from [::1]:46044
2016-11-06 02:08:35,769 INFO [6052:MpdSession-746] mopidy.mpd.session: New MPD connection from [::1]:46046
2016-11-06 02:09:05,826 INFO [6052:MpdSession-747] mopidy.mpd.session: New MPD connection from [::1]:46048
# then it just changes to this at the point where it stops:
2016-11-06 02:09:37,857 WARNING [6052:MainThread] mopidy.internal.network: Rejected connection from [::1]:46050
2016-11-06 02:09:37,878 WARNING [6052:MainThread] mopidy.internal.network: Rejected connection from [::1]:46052
2016-11-06 02:09:37,900 WARNING [6052:MainThread] mopidy.internal.network: Rejected connection from [::1]:46054
2016-11-06 02:09:39,923 WARNING [6052:MainThread] mopidy.internal.network: Rejected connection from [::1]:46056
2016-11-06 02:09:39,944 WARNING [6052:MainThread] mopidy.internal.network: Rejected connection from [::1]:46058
2016-11-06 02:09:39,964 WARNING [6052:MainThread] mopidy.internal.network: Rejected connection from [::1]:46060

/var/log/syslog

# same deal as mopidy.log. works fine:
Nov  6 02:08:03 hostname mopidy[6052]: INFO     New MPD connection from [::1]:46042
Nov  6 02:08:35 hostname mopidy[6052]: INFO     New MPD connection from [::1]:46044
Nov  6 02:08:35 hostname mopidy[6052]: INFO     New MPD connection from [::1]:46046
Nov  6 02:09:05 hostname mopidy[6052]: INFO     New MPD connection from [::1]:46048
# then begins failing with no extra info:
Nov  6 02:09:37 hostname mopidy[6052]: WARNING  Rejected connection from [::1]:46050
Nov  6 02:09:37 hostname mopidy[6052]: WARNING  Rejected connection from [::1]:46052
Nov  6 02:09:37 hostname mopidy[6052]: WARNING  Rejected connection from [::1]:46054
Nov  6 02:09:39 hostname mopidy[6052]: WARNING  Rejected connection from [::1]:46056
Nov  6 02:09:39 hostname mopidy[6052]: WARNING  Rejected connection from [::1]:46058
Nov  6 02:09:39 hostname mopidy[6052]: WARNING  Rejected connection from [::1]:46060
Nov  6 02:09:41 hostname mopidy[6052]: WARNING  Rejected connection from [::1]:46062

There doesn’t seem to be any info anywhere, it just… stops working forever.

What’s going on?

$ mpc version
mpd version: 0.19.0

I didn’t install or configure mopidy on this Pi, I’m actually taking over this project from somebody else and trying to work out the kinks, so I have to admit to not knowing much about how mopidy is set up. If there’s anything I can do to get more info let me know.

I’m not really sure how else to proceed. When I did a Google search for “mopidy.internal.network: Rejected connection from”, there was exactly one result (a rarity these days), and it was not related to this issue.

Thank you.

2 Likes
2

I just want to chime in that I’m having the exact same problem as well.
I’m running Mopidy 2.0.1-1 as service on a Raspberry Pi 1 model B running Raspbian GNU/Linux 8 (jessie).

1 Like
3

Also seeing the same thing (related to a HomeAssistant installation). I notice in my log that there are like 20 connections at the same time before mopidy starts rejecting. Is it just reaching its connection limit? Perhaps the client is freaking out and trying to make too many connections at once or something.

4

I don’t think it’s reaching any connection limit, the symptoms scream of some sort of memory/other resource leak in the server. I’d love to hear from the Mopidy dev team about this. It’s actually been a fairly large (and sometimes embarrassing) issue for the project I’m currently working on.

5

When you say you’ve seen a similar thing, is that also when running some kind of stress test or just from normal usage? Is this when using Spotify?

I don’t think there is any point debugging v0.19 so first step is to get a way to reliably reproduce this on the latest version.

6

Sorry @mnbv0987, I misread your post and thought you were running v0.19.X of Mopidy, presumably you are actually running a more recent 2.x version like the others here seeing this issue. Please correct me if I’m wrong.

  • Are you adding the same Spotify playlist every time in your stress test?
  • What model Rraspberry Pi are you using?

There is a connection limit defined by the config setting mpd/max_connections which will start rejecting new connections once it’s exceeded. The default is 20 connections.

It’s possible that once something goes wrong (the timeout) there is something preventing these errored connections from closing promptly. When Mopidy closes a connection it does some cleanup stuff which is not instantaneous. However, this stuff doesn’t block the client so mpc can go ahead and exit while Mopidy continues to do the cleanup. mpc may then go and initiate another connection before the first has actually finished closing, so for a window of time Mopidy sees two ‘open’ connections. Perhaps this snowballs until we hit the connection limit.

This effect would be more noticeable on a slow device, particularly one with really slow thread context switches, for example a Raspberry Pi.

It would be very useful if you could provide a debug log showing the issue. I’ll see if I can reproduce the issue on my system but I expect that I’ll need to do it on a raspberry pi.

7

I’m currently at 2041 iterations of what I think your stress test is doing and no problems so far. Note I am using a Raspberry Pi Model 2B.

#!/bin/bash 
COUNTER=0

while [ TRUE ]; do
    echo Iteration $COUNTER
    mpc -q clear
    mpc -q add spotify:user:grizzlyriggaz:playlist:0rAgBTjDlOvxbsbGapLzDw
    mpc -q play
    sleep 2
    let COUNTER=COUNTER+1 
done
8

The same is happening to me as well, however instead of spotify I am using Youtube extension and had lots of issues installing and configuring the youtube extension and now getting issues whenever i load a playlist from youtube. This is consistent as well. I have also homeassistant connecting to the system.