clementine-player / Clementine

:tangerine: Clementine Music Player
https://www.clementine-player.org/
GNU General Public License v3.0
3.72k stars 671 forks source link

Stuck buffering when playing a mixed spotify/local playlist #4038

Open justen opened 10 years ago

justen commented 10 years ago

When playing a playlist which contains both local and Spotify tracks, Clementine sometimes gets stuck buffering forever at track transitions. Clicking the next track button in the interface gets things working again. When this happens, the following appears in the console:

12:00:20.617 WARN  unknown                          QObject: Cannot create children for a parent that is in a different thread. 
12:00:20.617 WARN  unknown                          (Parent is SpotifyServer(0x3795870), parent's thread is QThread(0x1d0f2e0), current thread is QThread(0x7f62802e14d0) 
12:00:20.617 WARN  unknown                          QObject::startTimer: QTimer can only be used with threads started with QThread

I haven't been able to reproduce this with a very small playlist (i.e., one track local, one track from Spotify), but it happens pretty often on larger playlists.

justen commented 10 years ago

I think the problem is in the StartPlaybackLater method of SpotifyServer. When a track ends and Clementine moves on to the next, if I'm following this right, this is the code invoked:

void SpotifyServer::StartPlaybackLater(const QString& uri, quint16 port) {
  QTimer* timer = new QTimer(this);
  connect(timer, SIGNAL(timeout()), timer, SLOT(deleteLater()));

  timer->start(100); // lol
  NewClosure(timer, SIGNAL(timeout()),
             this, SLOT(StartPlayback(QString,quint16)),
             uri, port);
}

But if you just use the skip button to change tracks, this is used instead:-

void SpotifyServer::StartPlayback(const QString& uri, quint16 port) {
  pb::spotify::Message message;
  pb::spotify::PlaybackRequest* req = message.mutable_playback_request();

  req->set_track_uri(DataCommaSizeFromQString(uri));
  req->set_media_port(port);
  SendOrQueueMessage(message);
}

Skipping tracks manually works - and I think it's the creation of the QTimer in the first function that's causing the problem. Either the timer can't be created - according to the warnings because we're in the wrong thread - or it can't be started because we're not in a thread started with QThread. Whichever, the timer never starts so it can never kick StartPlayback. I'm not sure what the point is of the arbitrary 100ms countdown. Could it be removed completely? Or maybe just create a new QThread for the timer to count down in?

justen commented 10 years ago

Also, I take back the comment about not being able to reproduce this with a small playlist - with just one spotify and one local track, I get the stall every time Clementine tries to progress from local to spotify-based track under it's own steam. I was using very short test tracks before, and if you seek very close to the end of the local track (like, within a second of the end) and let it play from there, playback seems to proceed without any problems.

justen commented 10 years ago

Further to that, I just had a thought: It looks like the problem is related to the buffering time. I was skipping to less than the current buffer duration from the end of the track, which stops the stall from manifesting. On a hunch, I tried setting the buffer duration to 0 - and it looks like that stops playback from stalling. So that looks like a workaround at least.

cpieloth commented 10 years ago

I have this problem while playing a local/dynamic playlist with local files only (without any online content).

Problem: Track transition get stuck in a dynamic playlist with local files. The playlist jumps to the next track, but the song is not played and remains on second 0. After stopping the track and push play again or just switching to the next track, the playlist is working.

Expected behavior: After a track is played, the playlist switches to the next song and starts playing the new song.

Steps to Reproduce: Not available. Problem occurs very randomly, I would say once in 6 hours or even less.

System: Windows 7 64bit, I think, I had this problem on my linux workstation (Ubuntnu 12.04 LTS), too. Clementine 1.2.1 AMD Phenom II X4 4 GB RAM

cincodenada commented 9 years ago

I've been noticing @justen's issue as well - same symptoms, same log messages. A playlist that contains local and Spotify tracks, when it transitions from local to Spotify, playback stops. Manually skipping or double-clicking on the song in the playlist works just fine. I confirmed that it is still happening as of 56c9498, which is the latest version I can get to compile currently.

I can also confirm that if I skip very close to the end of the previous track, it goes through successfully. Here's a debug log from first skipping within a second or two of the end of the track and having it successfully continue, and then going back, skipping within ~10s of the end but not as close, and the error coming up:

21:34:54.886 INFO  Player:378                       Track seeked to 345000000000 ns - not scrobbling 
21:34:58.323 DEBUG unknown                          QMap(("album", "Brill Bruisers")("albumArtist", "")("artist", "The New Pornographers")("context", "")("duration", "176")("method", "Track.updateNowPlaying")("track", "Brill Bruisers"))  
21:34:58.332 DEBUG SpotifyClient:881                Image not loaded, will try again later 
21:34:58.361 DEBUG MainWindow:1152                  position 0 scrobble point 88 status 0 
21:34:58.434 DEBUG SpotifyClient:813                Playback track not loaded yet, will try again later 
21:34:58.515 INFO  SpotifyClient:833                Starting playback of uri spotify:track:0g6azQIxHsHFBoDD7BI3jz to port 50848 
21:34:58.947 DEBUG unknown                          "  <lfm status="ok"> 
21:34:58.947 DEBUG unknown                              <nowplaying> 
21:34:58.947 DEBUG unknown                                <track corrected="0">Brill Bruisers</track> 
21:34:58.947 DEBUG unknown                                <artist corrected="0">The New Pornographers</artist> 
21:34:58.947 DEBUG unknown                                <album corrected="0">Brill Bruisers</album> 
21:34:58.947 DEBUG unknown                                <albumArtist corrected="0"/> 
21:34:58.947 DEBUG unknown                                <ignoredMessage code="0"/> 
21:34:58.947 DEBUG unknown                              </nowplaying> 
21:34:58.947 DEBUG unknown                            </lfm> 
21:34:58.947 DEBUG unknown                          "  
21:34:59.026 DEBUG SpotifyClient:159                libspotify: "04:34:59.026 E [facebook_scrobbler.cpp:479] Error querying scrobble server error 0 result 500" 
21:34:59.370 DEBUG MainWindow:1152                  position 0 scrobble point 88 status 0 
21:35:03.136 DEBUG _MessageReplyBase:28             Waiting on ID 1 
21:35:03.136 DEBUG TagReader:758                    Loading art from "/home/joel/Music/The New Pornographers/Together/12 - We End Up Together.mp3" 
21:35:03.136 INFO  MoodbarLoader:106                Loading cached moodbar data for "/home/joel/Music/The New Pornographers/Together/12 - We End Up Together.mp3" 
TagLib: ID3v2.4 no longer supports the frame type TDAT.  It will be discarded from the tag.
21:35:03.137 DEBUG unknown                          QMap(("album", "Together")("albumArtist", "")("artist", "The New Pornographers")("context", "")("duration", "346")("method", "Track.updateNowPlaying")("track", "We End Up Together"))  
21:35:03.137 DEBUG MessageReply<MessageType>:93     Releasing ID 1 (finished) 
21:35:03.137 DEBUG _MessageReplyBase:30             Acquired ID 1 
21:35:03.196 DEBUG Playlist:1534                    Setting metadata for  QUrl( "file:///home/joel/Music/The New Pornographers/Together/12 - We End Up Together.mp3" )  to "The New Pornographers" "We End Up Together" 
21:35:03.196 DEBUG MainWindow:1152                  position 0 scrobble point 173 status 0 
21:35:03.756 DEBUG unknown                          "  <lfm status="ok"> 
21:35:03.756 DEBUG unknown                              <nowplaying> 
21:35:03.756 DEBUG unknown                                <track corrected="0">We End Up Together</track> 
21:35:03.756 DEBUG unknown                                <artist corrected="0">The New Pornographers</artist> 
21:35:03.756 DEBUG unknown                                <album corrected="0">Together</album> 
21:35:03.756 DEBUG unknown                                <albumArtist corrected="0"/> 
21:35:03.756 DEBUG unknown                                <ignoredMessage code="0"/> 
21:35:03.756 DEBUG unknown                              </nowplaying> 
21:35:03.756 DEBUG unknown                            </lfm> 
21:35:03.756 DEBUG unknown                          "  
21:35:04.883 INFO  Player:378                       Track seeked to 338000000000 ns - not scrobbling 
21:35:07.196 DEBUG MainWindow:1152                  position 340 scrobble point 173 status 2 
21:35:09.521 WARN  unknown                          QObject: Cannot create children for a parent that is in a different thread. 
21:35:09.521 WARN  unknown                          (Parent is SpotifyServer(0x2fb76c0), parent's thread is QThread(0x2868490), current thread is QThread(0x7fb430011b50) 
21:35:09.521 WARN  unknown                          QObject::startTimer: QTimer can only be used with threads started with QThread 
21:35:12.564 DEBUG SpotifyClient:159                libspotify: "04:35:12.564 E [ap:4172] ChannelError(0, 1, playlist)" 
cschreib commented 9 years ago

Running Linux, Clementine 1.2.3. I have the same issue with dynamic playlists, although my case seems a bit different.

My dynamic playlist only contain local files. Also, after I started having this bug, I tried to disable the dynamic loading of tracks, and just play the playlist frozen, as it is. The problem still happens. This is triggered randomly, but quite frequently. About once every 10 songs, if not less (last time: 8 songs, or 35 minutes and 16 seconds).

When a new track plays, sometimes the "progress bar" gets stuck at 0:01, and no sound is produced. I think once it started playing back on its own, without me touching anything, after a few minutes. The hang just happened to me right now, so I tried waiting again. It has now been more than 20 minutes, and Clementine is still stuck playing nothing, so I gave up.

Now, in this situation, if I press "pause", Clementine obeys. But if then I try to play the song again, by clicking the "play" button, Clementine refuses and the song remains paused. The only way out is to play another song (for example by clicking the "next" button), which starts immediately.

Contrary to the previous post, I found nothing particular in the debug output. The last entry is about the Moodbar, which says that the data has been successfully generated (that was the first time I played that song). This was printed a few instants after what was supposed to be the beginning of the next song.

cschreib commented 9 years ago

After some thoughts, I realized the above issue may not be related to this bug report, so I have opened a new one: https://github.com/clementine-player/Clementine/issues/4748

urinieto commented 9 years ago

Just wanted to mention that I have the exact problem as @justen. Any updates on this?

urinieto commented 9 years ago

Fyi, I am using Clementine Version 1.2.3 on Ubuntu 14.04.