search

PeteManchester / MediaPlayer

61 stars 20 forks source link

Next song in playlist not played, sometimes. #48

Closed Ghuru42 closed 4 years ago

Ghuru42 commented 9 years ago

Got an issue I cant get hold on. Sometimes, more often after mediaplayer been running for a while (days often), the next song in the playlist is not played. It just stopps.

Here is the output from mediaplayer.log set to debug level:

2015-07-14 18:11:09,925 [Thread-27] DEBUG [org.rpi.player.PlayManager] Set Volume: 47 2015-07-14 18:15:51,742 [Thread-0] DEBUG [org.rpi.player.PlayManager] Current Track is going to finish, get NextTrack and PreLoad 2015-07-14 18:15:51,743 [Thread-0] DEBUG [org.rpi.player.PlayManager] Getting Next Track, CurrentTrack is: http://10.190.0.10:9790/minimserver/*/MusicMartin/music/Amanda*20Jenssen/Killing*20My*20Darlings/03*20-*20Greetings*20from*20Space.flac 2015-07-14 18:15:51,743 [Thread-0] DEBUG [org.rpi.player.PlayManager] Returning Next Track: http://10.190.0.10:9790/minimserver/*/MusicMartin/music/Amanda*20Jenssen/Killing*20My*20Darlings/04*20-*20Do*20You*20Love*20Me.flac 2015-07-14 18:15:51,743 [Thread-0] DEBUG [org.rpi.mpdplayer.MPDPlayer] PreLoad Next Track: http://10.190.0.10:9790/minimserver/*/MusicMartin/music/Amanda*20Jenssen/Killing*20My*20Darlings/04*20-*20Do*20You*20Love*20Me.flac 2015-07-14 18:15:51,743 [Thread-0] DEBUG [org.rpi.radio.parsers.FileParser] FLAC File: http://10.190.0.10:9790/minimserver/*/MusicMartin/music/Amanda*20Jenssen/Killing*20My*20Darlings/04*20-*20Do*20You*20Love*20Me.flac 2015-07-14 18:15:53,751 [Thread-0] DEBUG [org.rpi.mpdplayer.StatusMonitor] Song Changed From : 20 To: 21 2015-07-14 18:15:53,751 [Thread-0] DEBUG [org.rpi.mpdplayer.MPDPlayer] Status Changed: Playing 2015-07-14 18:15:53,751 [Thread-0] DEBUG [org.rpi.player.PlayManager] EventStatusChanged: Playing 2015-07-14 18:15:53,751 [Thread-0] DEBUG [org.rpi.player.PlayManager] SetStatus: Playing 2015-07-14 18:15:53,753 [Thread-0] DEBUG [org.rpi.providers.PrvAVTransport] Status: Playing 2015-07-14 18:19:25,424 [Thread-0] DEBUG [org.rpi.player.PlayManager] Current Track is going to finish, get NextTrack and PreLoad 2015-07-14 18:19:25,424 [Thread-0] DEBUG [org.rpi.player.PlayManager] Getting Next Track, CurrentTrack is: http://10.190.0.10:9790/minimserver/*/MusicMartin/music/Amanda*20Jenssen/Killing*20My*20Darlings/04*20-*20Do*20You*20Love*20Me.flac 2015-07-14 18:19:25,424 [Thread-0] DEBUG [org.rpi.player.PlayManager] Returning Next Track: http://10.190.0.10:9790/minimserver/*/MusicMartin/music/Amanda*20Jenssen/Killing*20My*20Darlings/05*20-*20So*20Far*20Away.flac 2015-07-14 18:19:25,425 [Thread-0] DEBUG [org.rpi.mpdplayer.MPDPlayer] PreLoad Next Track: http://10.190.0.10:9790/minimserver/*/MusicMartin/music/Amanda*20Jenssen/Killing*20My*20Darlings/05*20-*20So*20Far*20Away.flac 2015-07-14 18:19:25,425 [Thread-0] DEBUG [org.rpi.radio.parsers.FileParser] FLAC File: http://10.190.0.10:9790/minimserver/*/MusicMartin/music/Amanda*20Jenssen/Killing*20My*20Darlings/05*20-*20So*20Far*20Away.flac 2015-07-14 18:19:28,529 [Thread-0] DEBUG [org.rpi.mpdplayer.StatusMonitor] Status Changed From : Playing To: Stopped 2015-07-14 18:19:28,535 [Thread-0] DEBUG [org.rpi.mpdplayer.MPDPlayer] Status Changed: Stopped 2015-07-14 18:19:28,535 [Thread-0] DEBUG [org.rpi.player.PlayManager] EventStatusChanged: Stopped 2015-07-14 18:19:28,535 [Thread-0] DEBUG [org.rpi.player.PlayManager] SetStatus: Stopped

2015-07-14 18:19:28,536 [Thread-0] DEBUG [org.rpi.providers.PrvAVTransport] Status: Stopped

It is adding the next song, but I think it's done just a fraction to late so mpd stops before the next song is present in the playlist.??

mpd is version 0.19.9, compiled by me. It's running under Raspbian on a Pi 2 board.

Any idéas or suggestions on what to test or log?

PeteManchester commented 9 years ago

Hi,

Sorry about the delay I've been on holiday. Looking at the log MediaPlayer is doing everything it should be doing..

It may be worth looking at the MPD logs to determine what is going wrong.

What should happen is that MPD has it's own playlist, normally there should only be one track in that playlist, when a track has finished MPD will delete that track from it's playlist. To enable gapless playback i get the track duration and then monitor how long is left for the track playing. At a configurable time before the end of the track I then add another track to the MPD playlist. Which MPD should then play next..

Mediaplayer gets the track duration from MPD, it gets status updates from MPD that contain the time played, it then works out when it should preload the next track to MPD. There are no errors when the track is preloaded to MPD and so the assumption is that the track was added to the MPD playlist successfully, on the track that fails the next track was preloaded 3 seconds before the stopped status is sent by MPD to MediaPlayer.

Things that could be wrong are that the track duration is incorrect (but I don't think so as the preload happens 3 seconds before the end of the current track. For some reason 3 seconds is not enough for MPD to add the track to the playlist. MPD does not like the track for some reason and so will not play it.

Try setting the MiediaPlayer option 'mpd.preload.timer' to a higher value to see if this solves the problem.

Cheers,

Pete.

Ghuru42 commented 9 years ago

I changed the preload timer to 10s, and verified in the log that it works. Still get the same issue. But, today I might have stumbled on to something.

Console output: root@gplayer:/opt/db/mediaplayer# mpc playlist DAD - Sleeping My Day Away http://10.10.1.10:9790/minimserver/*/FLAC/DAD*20-*20Good*20Clean*20Family*20Entertainment*20You*20Can*20Trust/03.*20Jihad.flac DAD - Bad Craziness root@gplayer:/opt/db/mediaplayer#

From Kazoo the playlist order is

The order mpc prints the playlist says it's wrong.. The "new" track is not last, but second to last. And the first track is still there..

I don´t have the debug log from mediaplayer for this event, it's just set to "info" at the moment.

Any suggestions?

Ghuru42 commented 9 years ago

If I press "next" in Kazoo it plays the "Jihad" track and "mpc playlist" returns just one row..

PeteManchester commented 9 years ago

Not sure what is going on there...

When a track is about to finish, in your case 10 seconds before the end a new track is inserted into the mpd playlist at index 1, so it could be the track Sleeping My Day Away was playing, MediaPlayer got the signal that it was about to finish and inserted Jihad, then somehow MediaPlayer got another signal that the track was about to finish and inserted Bad Craziness into position one pushing Jihad to position 2.

When you click Next, Mediaplayer stops the current track (if playing) and clears the playlist then plays the next track, so that would explain why the playlist is cleared..