search

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

ERROR logging:56, Stop the track and jump to the next. #5513

Open Fermman opened 7 years ago

Fermman commented 7 years ago

Before posting

Please follow the steps below and check the boxes with [x] once you did the step.

Please provide information about your system and the version of Clementine used.

Everytime I play music from spotify works below a minute and jump to the next track, in terminal when it happens, next lines appear:

10:33:37.327 INFO  SpotifyClient:961                Starting playback of uri spotify:track:07q0QVgO56EorrSGHC48y3 to port 64093 
10:33:37.336 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:33:37.397 DEBUG PlaylistBackend:294              Saving playlist 1 
10:33:37.987 DEBUG SpotifyClient:167                libspotify: "15:33:37.987 E [ap:4172] ChannelError(2, 1, link-tracks)" 
10:33:38.336 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:33:39.323 DEBUG SpotifyClient:167                libspotify: "15:33:39.323 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:33:40.169 DEBUG SpotifyClient:167                libspotify: "15:33:40.169 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:33:44.344 DEBUG SpotifyClient:167                libspotify: "15:33:44.344 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:33:52.966 ERROR SpotifyService:235               Spotify blob process failed: 1 
10:33:58.336 DEBUG MainWindow:1483                  position 20 scrobble point 135 status 0 
10:33:58.978 ERROR logging:56                       Source ID 256 was not found when attempting to remove it

Between jump of tracks:

10:39:09.603 INFO  SpotifyService:356               Starting "/home/fernando/.config/Clementine/spotifyblob/version16-64bit/blob" 
10:39:09.628 DEBUG MainWindow:1483                  position 0 scrobble point 124 status 0 
10:39:09.652 DEBUG SpotifyClient:84                 Using: "/home/fernando/.config/Clementine/spotify-cache" for Spotify cache 
10:39:09.652 DEBUG SpotifyClient:86                 Using: "/home/fernando/.config/Clementine/spotify-settings" for Spotify settings 
10:39:09.652 DEBUG SpotifyClient:114                Connecting to port 46733 
10:39:09.652 INFO  SpotifyServer:53                 Connection from port 41912 
10:39:09.653 DEBUG SpotifyClient:321                Setting playback settings: bitrate 1 normalisation false 
10:39:09.654 DEBUG SpotifyClient:167                libspotify: "15:39:09.654 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:39:09.659 DEBUG SpotifyClient:167                libspotify: "15:39:09.659 I [offline-mgr:2084] Storage has been cleaned" 
10:39:09.663 DEBUG SpotifyClient:167                libspotify: "15:39:09.663 I [ap:1752] Connecting to AP ap.spotify.com:4070" 
10:39:09.663 DEBUG SpotifyClient:1012               Image not loaded, will try again later 
10:39:09.664 DEBUG SpotifyClient:941                Playback track not loaded yet, will try again later 
10:39:10.152 DEBUG SpotifyClient:167                libspotify: "15:39:10.152 I [ap:1226] Connected to AP: 193.235.206.100:4070" 
10:39:10.628 DEBUG MainWindow:1483                  position 0 scrobble point 124 status 0 
10:39:11.628 DEBUG MainWindow:1483                  position 0 scrobble point 124 status 0 
10:39:12.628 DEBUG MainWindow:1483                  position 0 scrobble point 124 status 0 
10:39:13.628 DEBUG MainWindow:1483                  position 0 scrobble point 124 status 0 
10:39:13.640 INFO  SpotifyClient:961                Starting playback of uri spotify:track:0J6mQxEZnlRt9ymzFntA6z to port 61370 
10:39:14.628 DEBUG MainWindow:1483                  position 0 scrobble point 124 status 0 
10:39:15.628 DEBUG MainWindow:1483                  position 0 scrobble point 124 status 0 
10:39:15.827 DEBUG SpotifyClient:167                libspotify: "15:39:15.827 E [ap:4172] ChannelError(5, 0, playlist)" 
10:39:16.628 DEBUG MainWindow:1483                  position 0 scrobble point 124 status 0 
10:39:16.676 DEBUG SpotifyClient:167                libspotify: "15:39:16.676 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:39:17.658 DEBUG SpotifyClient:167                libspotify: "15:39:17.658 I [file_streamer_simple.cpp:769] Request for file a294ca9e0203699c560950cf52467e5e8283aa18 complete (code: 0)" 
10:39:18.616 DEBUG SpotifyClient:167                libspotify: "15:39:18.616 I [file_streamer_simple.cpp:769] Request for file a294ca9e0203699c560950cf52467e5e8283aa18 complete (code: 0)" 
10:39:21.673 DEBUG SpotifyClient:167                libspotify: "15:39:21.672 I [file_streamer_simple.cpp:769] Request for file a294ca9e0203699c560950cf52467e5e8283aa18 complete (code: 0)" 
10:39:26.365 DEBUG SpotifyClient:167                libspotify: "15:39:26.365 E [ap:4172] ChannelError(1, 0, playlist)" 
10:39:26.628 DEBUG MainWindow:1483                  position 10 scrobble point 124 status 0 
10:39:31.364 DEBUG SpotifyClient:167                libspotify: "15:39:31.364 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:39:31.677 DEBUG SpotifyClient:167                libspotify: "15:39:31.677 I [user_cache:135] UserCache::initiateGetUsers() will query for 3 users" 
10:39:31.934 DEBUG SpotifyClient:167                libspotify: "15:39:31.934 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:39:32.101 DEBUG SpotifyClient:167                libspotify: "15:39:32.101 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:39:33.090 DEBUG SpotifyClient:167                libspotify: "15:39:33.090 E [ap:4172] ChannelError(1, 1, link-tracks)" 
10:39:33.907 DEBUG SpotifyClient:167                libspotify: "15:39:33.907 E [ap:4172] ChannelError(1, 1, link-tracks)" 
10:39:34.728 DEBUG SpotifyClient:167                libspotify: "15:39:34.728 I [file_streamer_simple.cpp:769] Request for file a294ca9e0203699c560950cf52467e5e8283aa18 complete (code: 0)" 
10:39:34.823 DEBUG SpotifyClient:167                libspotify: "15:39:34.822 E [ap:4172] ChannelError(1, 1, link-tracks)" 
10:39:46.993 DEBUG SpotifyClient:167                libspotify: "15:39:46.993 I [file_streamer_simple.cpp:769] Request for file a294ca9e0203699c560950cf52467e5e8283aa18 complete (code: 0)" 
10:39:46.993 DEBUG SpotifyClient:167                libspotify: "15:39:46.993 E [ap:4172] ChannelError(2, 1, playlist-info)" 
10:39:47.083 DEBUG SpotifyClient:167                libspotify: "15:39:47.083 E [ap:4172] ChannelError(1, 0, playlist)" 
10:39:47.432 DEBUG SpotifyClient:167                libspotify: "15:39:47.432 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:39:56.628 DEBUG MainWindow:1483                  position 40 scrobble point 124 status 0 
10:39:59.033 DEBUG SpotifyClient:167                libspotify: "15:39:59.033 I [file_streamer_simple.cpp:769] Request for file a294ca9e0203699c560950cf52467e5e8283aa18 complete (code: 0)" 
10:40:03.282 DEBUG SpotifyClient:167                libspotify: "15:40:03.282 E [ap:4172] ChannelError(11, 1, playlist)" 
10:40:15.501 DEBUG SpotifyClient:167                libspotify: "15:40:15.501 I [file_streamer_simple.cpp:769] Request for file a294ca9e0203699c560950cf52467e5e8283aa18 complete (code: 0)" 
10:40:15.857 ERROR SpotifyService:235               Spotify blob process failed: 1 
10:40:15.858 DEBUG MainWindow:1483                  position 60 scrobble point 124 status 0 
10:40:16.628 DEBUG MainWindow:1483                  position 60 scrobble point 124 status 0 
10:40:22.593 ERROR logging:56                       Source ID 358 was not found when attempting to remove it 
10:40:22.600 DEBUG PlaylistBackend:294              Saving playlist 1 
10:40:22.601 INFO  SpotifyService:356               Starting "/home/fernando/.config/Clementine/spotifyblob/version16-64bit/blob" 
10:40:22.640 DEBUG SpotifyClient:84                 Using: "/home/fernando/.config/Clementine/spotify-cache" for Spotify cache 
10:40:22.641 DEBUG SpotifyClient:86                 Using: "/home/fernando/.config/Clementine/spotify-settings" for Spotify settings 
10:40:22.641 DEBUG SpotifyClient:114                Connecting to port 43607 
10:40:22.648 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:40:22.648 INFO  SpotifyServer:53                 Connection from port 38946 
10:40:22.649 DEBUG SpotifyClient:321                Setting playback settings: bitrate 1 normalisation false 
10:40:22.651 DEBUG SpotifyClient:167                libspotify: "15:40:22.651 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:40:22.659 DEBUG SpotifyClient:167                libspotify: "15:40:22.659 I [ap:1752] Connecting to AP ap.spotify.com:4070" 
10:40:22.733 DEBUG SpotifyClient:167                libspotify: "15:40:22.733 I [offline-mgr:2084] Storage has been cleaned" 
10:40:22.733 DEBUG SpotifyClient:1012               Image not loaded, will try again later 
10:40:22.733 DEBUG SpotifyClient:941                Playback track not loaded yet, will try again later 
10:40:22.804 DEBUG SpotifyClient:167                libspotify: "15:40:22.804 I [ap:1226] Connected to AP: 23.92.108.228:4070" 
10:40:23.648 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:40:23.848 INFO  SpotifyClient:961                Starting playback of uri spotify:track:07q0QVgO56EorrSGHC48y3 to port 58051 
10:40:24.648 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:40:25.648 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:40:26.648 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:40:27.648 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:40:28.135 DEBUG SpotifyClient:167                libspotify: "15:40:28.134 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:40:28.648 DEBUG MainWindow:1483                  position 0 scrobble point 135 status 0 
10:40:31.362 DEBUG SpotifyClient:167                libspotify: "15:40:31.362 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:40:36.231 DEBUG SpotifyClient:167                libspotify: "15:40:36.231 E [ap:4172] ChannelError(6, 0, playlist)" 
10:40:38.648 DEBUG MainWindow:1483                  position 10 scrobble point 135 status 0 
10:40:47.493 DEBUG SpotifyClient:167                libspotify: "15:40:47.493 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:40:47.494 DEBUG SpotifyClient:167                libspotify: "15:40:47.494 E [ap:4172] ChannelError(0, 0, playlist)" 
10:40:48.648 DEBUG MainWindow:1483                  position 20 scrobble point 135 status 0 
10:40:58.648 DEBUG MainWindow:1483                  position 30 scrobble point 135 status 0 
10:41:04.518 DEBUG SpotifyClient:167                libspotify: "15:41:04.518 E [ap:4172] ChannelError(0, 0, playlist)" 
10:41:04.956 DEBUG SpotifyClient:167                libspotify: "15:41:04.956 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:41:08.648 DEBUG MainWindow:1483                  position 40 scrobble point 135 status 0 
10:41:11.819 DEBUG SpotifyClient:167                libspotify: "15:41:11.819 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:41:15.414 DEBUG SpotifyClient:167                libspotify: "15:41:15.414 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:41:15.968 DEBUG SpotifyClient:167                libspotify: "15:41:15.967 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:41:16.783 DEBUG SpotifyClient:167                libspotify: "15:41:16.783 I [user_cache:135] UserCache::initiateGetUsers() will query for 3 users" 
10:41:18.491 DEBUG SpotifyClient:167                libspotify: "15:41:18.491 E [ap:4172] ChannelError(6, 1, link-tracks)" 
10:41:18.491 DEBUG SpotifyClient:432                Got playlist 0 false 0  
10:41:18.491 INFO  SpotifyClient:436                Playlist is not loaded yet, waiting... 
10:41:18.491 DEBUG SpotifyClient:432                Got playlist 0 false 0  
10:41:18.491 INFO  SpotifyClient:436                Playlist is not loaded yet, waiting... 
10:41:18.491 DEBUG SpotifyClient:432                Got playlist 0 false 0  
10:41:18.491 INFO  SpotifyClient:436                Playlist is not loaded yet, waiting... 
10:41:18.491 DEBUG SpotifyClient:432                Got playlist 0 false 0  
10:41:18.491 INFO  SpotifyClient:436                Playlist is not loaded yet, waiting... 
10:41:18.491 DEBUG SpotifyClient:167                libspotify: "15:41:18.491 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:41:18.648 DEBUG MainWindow:1483                  position 50 scrobble point 135 status 0 
10:41:20.746 DEBUG SpotifyClient:167                libspotify: "15:41:20.746 E [ap:4172] ChannelError(4, 1, link-tracks)" 
10:41:23.511 DEBUG SpotifyClient:167                libspotify: "15:41:23.511 E [ap:4172] ChannelError(3, 1, link-tracks)" 
10:41:25.197 DEBUG SpotifyClient:167                libspotify: "15:41:25.197 E [ap:4172] ChannelError(3, 1, link-tracks)" 
10:41:26.726 DEBUG SpotifyClient:167                libspotify: "15:41:26.726 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:41:28.648 DEBUG MainWindow:1483                  position 60 scrobble point 135 status 0 
10:41:34.484 DEBUG SpotifyClient:167                libspotify: "15:41:34.484 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:41:34.852 DEBUG SpotifyClient:167                libspotify: "15:41:34.852 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:41:47.571 DEBUG SpotifyClient:167                libspotify: "15:41:47.571 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:41:47.694 DEBUG SpotifyClient:167                libspotify: "15:41:47.694 E [ap:4172] ChannelError(9, 1, playlist)" 
1
10:41:47.780 DEBUG SpotifyClient:167                libspotify: "15:41:47.780 E [ap:4172] ChannelError(12, 1, playlist)" 
10:41:47.780 DEBUG SpotifyClient:167                libspotify: "15:41:47.780 E [ap:4172] ChannelError(18, 1, playlist)" 
10:41:47.780 DEBUG SpotifyClient:432                Got playlist 0 false 0  
10:41:59.329 DEBUG SpotifyClient:167                libspotify: "15:41:59.329 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:42:11.993 DEBUG SpotifyClient:167                libspotify: "15:42:11.993 I [file_streamer_simple.cpp:769] Request for file e0170d6eb4f51b9398480858cd2d37fdafb6895e complete (code: 0)" 
10:42:12.290 DEBUG SpotifyClient:167                libspotify: "15:42:12.290 I [user_cache:135] UserCache::initiateGetUsers() will query for 1 users" 
10:42:12.994 ERROR SpotifyService:235               Spotify blob process failed: 1 
10:42:18.648 DEBUG MainWindow:1483                  position 110 scrobble point 135 status 0 
10:42:22.415 ERROR logging:56                       Source ID 691 was not found when attempting to remove it

Same behavior with the next track at the end of playlist, is like closing and re-log the spotify account, to play the music, or something like that.

Steps to reproduce the problem (only for bugs)

beurtbalkje commented 7 years ago

I can confirm the same behaviour for over a year now: openSUSE LEAP 42.2 (and LEAP 42.1 before the release of 42.2) with: clementine 1.3.1

It happens only with spotify, not with local music or e.g. soundcloud. I started clementine with this command: clementine --verbose 2>&1 | tee clementineout.txt This is part of the logfile, about a second before and during the skipping to the next spotify-item in the playlist:

11:51:42.060 ERROR SpotifyService:235 Spotify blob process failed: 1 11:51:55.360 DEBUG unknown "sni-qt/11985" INFO 11:51:55.359 void StatusNotifierItem::slotAboutToShow() Adding an "Activate" entry to the StatusNotifierItem context menu
11:52:06.079 DEBUG PlaylistBackend:294 Saving playlist 1 11:52:06.086 INFO SpotifyService:356 Starting "~/spotifyblob/version16-64bit/blob" 11:52:06.110 DEBUG GstEnginePipeline:519 1 sync bus message state-changed 11:52:06.119 DEBUG GstEnginePipeline:519 1 sync bus message state-changed 11:52:06.120 DEBUG GstEnginePipeline:519 1 sync bus message state-changed 11:52:06.120 DEBUG GstEnginePipeline:519 1 sync bus message state-changed

Hope this helpes, because this error is a waste of a very usefull app: I use spotify playlists on a daily basis and would very much like to combine them with local music in clementine.