search

turbowookie / turbo-wookie

Turbo Wookie Project. Because Turbo Wookie
http://turbowookie.github.io
BSD 3-Clause "New" or "Revised" License
9 stars 2 forks source link

The server breaks on random song. #23

Open mpeterson2 opened 10 years ago

mpeterson2 commented 10 years ago

I'm not sure what other info is helpful on this one...

Here's my console output:

2013/12/17 18:57:21 Starting MPD
2013/12/17 18:57:21 Staring mpdWatcher for localhost:6600
2013/12/17 18:57:21 Starting server on :9000
2013/12/17 19:06:00 MPD Watcher Error!
 EOF
2013/12/17 19:06:15 MPD Watcher Error!
 write tcp 127.0.0.1:6600: broken pipe
2013/12/17 19:06:30 MPD Watcher Error!
 write tcp 127.0.0.1:6600: broken pipe
2013/12/17 19:06:45 MPD Watcher Error!
 write tcp 127.0.0.1:6600: broken pipe
2013/12/17 19:07:00 MPD Watcher Error!
 write tcp 127.0.0.1:6600: broken pipe
2013/12/17 19:07:15 MPD Watcher Error!
 write tcp 127.0.0.1:6600: broken pipe
2013/12/17 19:07:30 MPD Watcher Error!
 write tcp 127.0.0.1:6600: broken pipe
2013/12/17 19:07:46 MPD Watcher Error!
 write tcp 127.0.0.1:6600: broken pipe
2013/12/17 19:07:46 ERROR: Couldn't turn current song's position to int
    strconv.ParseInt: parsing "": invalid syntax
2013/12/17 19:07:46 Sending to client: Couldn't get upcoming playlist
2013/12/17 19:07:46 http: proxy error: net/http: transport closed before response was received
2013/12/17 19:08:01 MPD Watcher Error!
 write tcp 127.0.0.1:6600: broken pipe
sleepdeprecation commented 10 years ago

Yes, I've noticed that random songs sometimes break... I thought it was because I was doing unnatural things...

The problem is that something killed the watcher. I think broken pipe is "code" for "we've been disconnected from the server".

Possible solutions:

  1. Attempt to reconnect when this happens.
  2. Kill everything when this happens, because we're all alone and nobody loves us.
  3. Pray it stops breaking pipes. Those can get expensive.
mpeterson2 commented 10 years ago

I think solution 1 is the way to go. We probably don't want to kill everything and I don't think praying is going to help us.

sleepdeprecation commented 10 years ago

Okay, so results:

The problem exists because no clients are connected, and for some reason putting something in a channel is blocking (or so it appears). Basically, when the Watcher calls Handler.PolarClient (used to tell clients something changed), and there are no clients, that function never releases control back.

To fix that, we just run Handler.PolarClient in a goroutine instead.

Commit coming as soon as I get rid of my debug comments.

sleepdeprecation commented 10 years ago

Better fix: instead of running it as a goroutine (which could cause problems), we just don't do anything if there aren't any clients connected to our long-poller.

mpeterson2 commented 10 years ago

I think there's a new issue now. Here's my output:

2013/12/17 20:05:20 MPD Watcher Error!
 EOF
2013/12/17 20:05:20 Restarting MPD Watcher
2013/12/17 20:05:20 Subsystem changed: player
2013/12/17 20:07:24 http: proxy error: read tcp 127.0.0.1:8000: connection reset by peer
2013/12/17 20:07:24 ERROR: Couldn't turn current song's position to int
    strconv.ParseInt: parsing "": invalid syntax
2013/12/17 20:07:24 Sending to client: Couldn't get upcoming playlist
2013/12/17 20:07:54 ERROR: Couldn't turn current song's position to int
    strconv.ParseInt: parsing "": invalid syntax
2013/12/17 20:07:54 Sending to client: Couldn't get upcoming playlist
2013/12/17 20:07:54 http: proxy error: read tcp 127.0.0.1:8000: connection reset by peer
sleepdeprecation commented 10 years ago

MPD Watcher restarted, and that's the end of that. It's going fine.

Errors at 07:24 - 07:54 are all TWHandler errors (you can tell because they say "ERROR" and "Sending to client"). The proxy error typically shows up when you kill MPD and the client trys to connect to it.

Restarting the watcher shouldn't kill MPD. Is MPD still running?

mpeterson2 commented 10 years ago

I'm not sure, but I'll check when it happens again (it happens a lot less). The server isn't sending the client any data anymore though.

sleepdeprecation commented 10 years ago

Typically those issues show up when MPD is absent. Which is weird, because our TWMPDClient should be the one with errors, not the TWHandler.

Like the error at 07:24: strconv.ParseInt: parsing "": invalid syntax: the empty string passed in there shouldn't be an empty string. An error should happen before that when we ask the server for that information, in the TWMPDClient.

Again, typically the errors are when MPD isn't around anymore. We might be accidentally killing it with the MPD Watcher restart, but based on the fact that we're told the player subsystem changed, it looks like MPD's still around.

It could be that MPD stopped playback. Try an mpc status. Or, if you're feeling adventurous, telnet into MPD (telnet localhost 6600, and ask for the status straight from the source status). I've found telnetting to give us better information than mpc and gompd.

mpeterson2 commented 10 years ago

Well I telnetted and asked for status and it told me

volume: -1
repeat: 0
random: 0
single: 0
consume: 0
playlist: 105
playlistlength: 80
xfade: 0
mixrampdb: 0.000000
mixrampdelay: nan
state: stop

Then I told it to play and refreshed the turbo wookie page. It played, but now there's like 100 songs in my playlist that I didn't add.

sleepdeprecation commented 10 years ago

Something funky was happening before it could play the stream... Which is weird, because mpdWatcher.queueSong fatals out if something bad happens...

Are you sure MPD didn't just lose your position in the playlist, and those 105 songs are all the songs you've played since the last time you cleared the playlist? Like manually cleared the playlist? Because Turbo Wookie doesn't do that (there's an issue I'm going to open eventually about other things the watcher could do).

mpeterson2 commented 10 years ago

I for sure did not manually clear the playlist. All that happened was Turbo Wookie switched songs, when there was no song in the upcoming list, and then that stuff happened.

sleepdeprecation commented 10 years ago

It might've just reset the queue?

mpeterson2 commented 10 years ago

I have no idea. Why would it have done that though?

mpeterson2 commented 10 years ago

It just happened again. Anything you want me to check?

sleepdeprecation commented 10 years ago

Yes:

mpeterson2 commented 10 years ago 
status
volume: -1
repeat: 0
random: 0
single: 0
consume: 0
playlist: 108
playlistlength: 2
xfade: 0
mixrampdb: 0.000000
mixrampdelay: nan
state: stop
OK

Here's the entire log from when I started the server till now.

2013/12/17 21:09:30 Starting MPD
2013/12/17 21:09:31 Staring mpdWatcher for localhost:6600
2013/12/17 21:09:31 Starting server on :9000
2013/12/17 21:09:31 Subsystem changed: player
2013/12/17 21:09:31 Subsystem changed: player
2013/12/17 21:13:21 Subsystem changed: player
2013/12/17 21:13:21 Subsystem changed: playlist
2013/12/17 21:13:21 Subsystem changed: player
2013/12/17 21:16:39 ERROR: Couldn't turn current song's position to int
    strconv.ParseInt: parsing "": invalid syntax
2013/12/17 21:16:39 Sending to client: Couldn't get upcoming playlist
2013/12/17 21:16:39 http: proxy error: net/http: transport closed before response was received
2013/12/17 21:17:15 ERROR: Couldn't turn current song's position to int
    strconv.ParseInt: parsing "": invalid syntax
2013/12/17 21:17:15 Sending to client: Couldn't get upcoming playlist
2013/12/17 21:17:15 http: proxy error: EOF
2013/12/17 21:18:04 ERROR: Couldn't turn current song's position to int
    strconv.ParseInt: parsing "": invalid syntax
2013/12/17 21:18:04 Sending to client: Couldn't get upcoming playlist
2013/12/17 21:18:04 http: proxy error: read tcp 127.0.0.1:8000: connection reset by peer

This is all that's relevant to today:

Dec 17 03:45 : client: No such directory
Dec 17 03:45 : client: No such directory
Dec 17 21:00 : player_thread: played "A Day to Remember/What Separates Me from You/04 This Is the House That Doubt B.mp3"
Dec 17 21:04 : player_thread: played "A Day to Remember/Violence _Enough Is Enough_-Si/00 Violence _Enough is Enough__mp.mp3"
mpeterson2 commented 10 years ago

I also just refreshed the page, and it is playing again. Although it didn't when I refreshed when it first broke and I haven't done anything (except what I posted above) since then.

sleepdeprecation commented 10 years ago

Weird. So the playlist is restarting?

mpeterson2 commented 10 years ago

No. I forgot to mention that there was only 1 song playing.

sleepdeprecation commented 10 years ago

So the only thing that's happening is MPD is stopping? Did a song end?

Reevaluating what those errors are saying: the root error is 21:16:39: Couldn't turn current song's position to int. It comes from TWMPDClient:236. The implication is that MPD isn't playing anything, because current doesn't have a "Pos" attribute.

You could put a print on line 233/234, print out the currentSong map.

At some point the stream is restarting, but I can't figure out where. Or, it's restarting exactly where we expect it to be, but there's a perceivable delay by the client, meaning it didn't restart fast enough. Perhaps ask the client to try restarting the stream? And limit it to five attempts or something, so it doesn't just continuously ask for info.

mpeterson2 commented 10 years ago

Annoyingly enough, I can't seem to get it to happen using mpc next. I'll just have to leave it running until it finally breaks. I put the print in so I'll let you know what happens when it breaks.

Oh and it happens when a song ends and there's nothing left in the playlist (I think that's what you were asking with the first line of your comment).

sleepdeprecation commented 10 years ago

I've had it stop playing too, while just running Turbo Wookie without anything else (I've got MPD outputting to my speakers).

mpeterson2 commented 10 years ago

It hasn't happened in quite a while now...

mpeterson2 commented 10 years ago

It finally broke. Here's a normal print of the map:

2013/12/17 22:33:36 map[file:30 Seconds To Mars/Love Lust Faith _ Dreams/09 Dor Or Die.mp3 AlbumArtist:30 Seconds To Mars Track:9/0 Date:2013 Disc:0/0 Pos:43 Id:127 Last-Modified:2013-12-15T02:12:36Z Time:248 Artist:30 Seconds To Mars Title:Dor Or Die Album:Love Lust Faith + Dreams Genre:Rock]

And here's the print after it broke:

2013/12/17 22:35:24 map[]
sleepdeprecation commented 10 years ago

Perhaps we should have gompd return nil or an error if you ask for the current song and MPD isn't playing? It's more informative than "you got an empty map back", which could just mean silly things (especially because you can ask MPD to format things for you).

sleepdeprecation commented 10 years ago

So that didn't fix it. Now the problem comes from our reverse proxy. Well, still comes from...

mpeterson2 commented 10 years ago

So I'm not 100% sure if this is the same situation, but I messed around with Dart server stuff, and I rewrote Turbo Wookie's backend in Dart. I had this same problem for a while, and I believe it had to do with the way I talked to MPD.

If I requested something, I would sometimes close my socket before MPD was done giving me data, and then I got a broken pipe exception and my server died (Strangely enough, I couldn't catch that exception).

It could be the same issue, or it could be completely unrelated, but it may be worth looking into.

sleepdeprecation commented 10 years ago

Doesn't count. Making a Dart-based fork and having this issue is different...

Also, why? Is Go not good enough for you? Because if so you're not good enough for Go. Go is FANTASTIC.

Server = dart server or MPD?

mpeterson2 commented 10 years ago

What doesn't count for what?

And the issue was MPD wanting to give us data but the socket was closed. Not that my Dart code was looking for data and the socket was closed. I don't know exactly how we communicate with MPD, so for all I know, it could be relevant.

I made it because I wanted something to do and I wanted to know what Dart servers were like. I probably won't work on it anymore, because this one is more important, but it did work out pretty well for the most part.

I'm not sure what your asking here?

sleepdeprecation commented 10 years ago

You completely changed the backend. All previous issues are no longer applicable, and any new issues don't apply to the original backend. Hence "Doesn't count.".

Does MPD want to give us data? Considering it's a traditional server model (IE: it sits and waits for requests, and doesn't track anything unless a TCP connection is still open. As soon as the connection closes the server forgets it every happened), I don't think MPD is telling us things when the pipes break, I think the most obvious reason is that we're keeping a connection open too long.

Especially because when using telnet to talk to MPD the pipe doesn't break, and that's one long TCP connection.

Have we tried upping the timeout on the client end?

mpeterson2 commented 10 years ago

I had the same issue while trying to do the same thing. It's not the exact same code, but it's still relevant. If it's not relevant enough for you then I don't really care, it is for me.

This happened yesterday and I did a lot of work since then so I'm a little fuzzy about it. I believe you are right, the problem was the socket was open for too long. I didn't stop listening to the connection because MPD didn't say OK\n at the end (like it normally does). Then issues happened.

I'm not sure what you've tried, but I haven't messed with this issue (here) besides talking to you about it.