GNOME Bugzilla – Bug 629541
[gapless] Crashes on changing track with an ObjectDisposedException from HyenaSqliteCommand.Execute
Last modified: 2020-03-17 08:50:16 UTC
I find that Banshee frequently crashes when changing track. I have found no further pattern to why this occurs. It appears to be a use-after-free. (I thought we lived in the future now and such issues were a thing of the past?) Here's the end of `banshee --debug --debug-sql`: [1 Warn 17:53:14.945] HyenaSqliteConnection command issued from the main thread [2 Debug 17:53:14.950] Executed in 4ms SELECT CoreAlbums.AlbumID,CoreAlbums.ArtistID,CoreAlbums.MusicBrainzID,CoreAlbums.ReleaseDate,CoreAlbums.IsCompilation,CoreAlbums.Title,CoreAlbums.TitleSort,CoreAlbums.ArtistName,CoreAlbums.ArtistNameSort , OrderID, CoreCache.ItemID FROM CoreAlbums INNER JOIN CoreCache ON CoreAlbums.AlbumID = CoreCache.ItemID WHERE CoreCache.ModelID = 7 LIMIT 0, 40 [1 Warn 17:53:14.956] HyenaSqliteConnection command issued from the main thread [2 Debug 17:53:14.960] Executed in 3ms SELECT CoreArtists.ArtistID,CoreArtists.Name,CoreArtists.NameSort,CoreArtists.MusicBrainzID , OrderID, CoreCache.ItemID FROM CoreArtists INNER JOIN CoreCache ON CoreArtists.ArtistID = CoreCache.ItemID WHERE CoreCache.ModelID = 5 LIMIT 0, 40 [2 Debug 17:53:15.064] Executed in 18ms DELETE FROM CoreSmartPlaylistEntries WHERE SmartPlaylistID = 2; INSERT INTO CoreSmartPlaylistEntries (EntryID, SmartPlaylistID, TrackID) SELECT NULL, 2 as SmartPlaylistID, TrackId FROM CoreTracks,CoreArtists,CoreAlbums WHERE CoreArtists.ArtistID = CoreTracks.ArtistID AND CoreAlbums.AlbumID = CoreTracks.AlbumID AND CoreTracks.PrimarySourceID = 1 AND (((CoreTracks.LastPlayedStamp > 1283793803 AND CoreTracks.LastPlayedStamp IS NOT NULL) And (CoreTracks.PlayCount > 3 AND CoreTracks.PlayCount IS NOT NULL))) [2 Debug 17:53:15.091] Executed in 27ms SELECT COUNT(*), SUM(CoreTracks.FileSize) FROM CoreTracks CROSS JOIN CoreArtists,CoreAlbums, CoreSmartPlaylistEntries WHERE CoreArtists.ArtistID = CoreTracks.ArtistID AND CoreAlbums.AlbumID = CoreTracks.AlbumID AND CoreSmartPlaylistEntries.TrackID = CoreTracks.TrackID AND CoreSmartPlaylistEntries.SmartPlaylistID = 2 [2 Debug 17:53:15.123] Executed in 32ms DELETE FROM CoreCache WHERE ModelID = 25; INSERT INTO CoreCache (ModelID, ItemID) SELECT 25, CoreTracks.TrackID FROM CoreTracks CROSS JOIN CoreArtists,CoreAlbums, CoreSmartPlaylistEntries WHERE CoreArtists.ArtistID = CoreTracks.ArtistID AND CoreAlbums.AlbumID = CoreTracks.AlbumID AND CoreSmartPlaylistEntries.TrackID = CoreTracks.TrackID AND CoreSmartPlaylistEntries.SmartPlaylistID = 2 ORDER BY CoreArtists.NameSortKey ASC, CoreTracks.Year ASC, CoreAlbums.TitleSortKey ASC, CoreTracks.Disc ASC, CoreTracks.TrackNumber ASC [2 Debug 17:53:15.124] Executed in 0ms BEGIN TRANSACTION [2 Debug 17:53:15.132] Executed in 7ms DELETE FROM CoreCache WHERE ModelID = 19; INSERT INTO CoreCache (ModelID, ItemID) SELECT 19, CoreArtists.ArtistID FROM CoreArtists WHERE CoreArtists.ArtistID IN (SELECT CoreTracks.ArtistID FROM CoreTracks, CoreCache WHERE CoreCache.ModelID = 25 AND CoreCache.ItemID = CoreTracks.TrackID ) ORDER BY NameSortKey [2 Debug 17:53:15.135] Executed in 3ms SELECT COUNT(*) FROM CoreCache WHERE ModelID = 19 [2 Debug 17:53:15.135] Executed in 0ms COMMIT TRANSACTION [2 Debug 17:53:15.136] Executed in 0ms BEGIN TRANSACTION [2 Debug 17:53:15.144] Executed in 8ms DELETE FROM CoreCache WHERE ModelID = 21; INSERT INTO CoreCache (ModelID, ItemID) SELECT 21, CoreAlbums.AlbumID FROM CoreAlbums WHERE CoreAlbums.AlbumID IN (SELECT CoreTracks.AlbumID FROM CoreTracks, CoreCache WHERE CoreCache.ModelID = 25 AND CoreCache.ItemId = CoreTracks.TrackID ) ORDER BY CoreAlbums.TitleSortKey, CoreAlbums.ArtistNameSortKey [2 Debug 17:53:15.148] Executed in 4ms SELECT COUNT(*) FROM CoreCache WHERE ModelID = 21 [2 Debug 17:53:15.148] Executed in 0ms COMMIT TRANSACTION [2 Debug 17:53:15.148] Executed in 0ms BEGIN TRANSACTION [2 Debug 17:53:15.156] Executed in 7ms DELETE FROM CoreCache WHERE ModelID = 23; INSERT INTO CoreCache (ModelID, ItemID) SELECT DISTINCT 23, Genre as Value FROM CoreTracks, CoreCache WHERE CoreCache.ModelID = 25 AND CoreCache.ItemID = CoreTracks.TrackID ORDER BY Value [2 Debug 17:53:15.159] Executed in 3ms SELECT COUNT(*) FROM CoreCache WHERE ModelID = 23 [2 Debug 17:53:15.160] Executed in 0ms COMMIT TRANSACTION [2 Debug 17:53:15.164] Executed in 3ms SELECT count(*), SUM(CoreTracks.Duration), SUM(CoreTracks.FileSize) FROM CoreTracks WHERE CoreTracks.TrackID IN (SELECT ItemID FROM CoreCache WHERE ModelID = 25) [2 Debug 17:53:15.165] Executed in 0ms UPDATE CoreSmartPlaylists SET Name = 'Recent Favorites', Condition = '<request><query banshee-version="1"><and><lessThan><field name="lastplayed" /><date factor="Week" type="rel">-604800</date></lessThan><greaterThan><field name="playcount" /><int>3</int></greaterThan></and></query></request>', OrderBy = NULL, LimitNumber = NULL, LimitCriterion = NULL, CachedCount = 79, IsTemporary = 0 WHERE SmartPlaylistID = 2 [2 Debug 17:53:15.244] Executed in 63ms DELETE FROM CoreSmartPlaylistEntries WHERE SmartPlaylistID = 7; INSERT INTO CoreSmartPlaylistEntries (EntryID, SmartPlaylistID, TrackID) SELECT NULL, 7 as SmartPlaylistID, TrackId FROM CoreTracks,CoreArtists,CoreAlbums WHERE CoreArtists.ArtistID = CoreTracks.ArtistID AND CoreAlbums.AlbumID = CoreTracks.AlbumID AND CoreTracks.PrimarySourceID = 1 AND ((CoreTracks.LastPlayedStamp < 1268846604 OR CoreTracks.LastPlayedStamp IS NULL)) Unhandled Exception: System.ObjectDisposedException: The object was used after being disposed. at System.Threading.WaitHandle.CheckDisposed () [0x00000] at System.Threading.EventWaitHandle.Reset () [0x00000] at (wrapper remoting-invoke-with-check) System.Threading.EventWaitHandle:Reset () at Hyena.Data.Sqlite.HyenaSqliteCommand.Execute (Hyena.Data.Sqlite.HyenaSqliteConnection hconnection, Mono.Data.Sqlite.SqliteConnection connection) [0x00182] in /tmp/buildd/banshee-1.7.4/src/Hyena/Hyena.Data.Sqlite/Hyena.Data.Sqlite/HyenaSqliteCommand.cs:134 at Hyena.Data.Sqlite.HyenaSqliteConnection.ProcessQueue () [0x000b2] in /tmp/buildd/banshee-1.7.4/src/Hyena/Hyena.Data.Sqlite/Hyena.Data.Sqlite/HyenaSqliteConnection.cs:442
It looks like your database file somehow gut corrupted. Did you experience a system crash, a power failure or something like that before this error started to happen ? You might be able to recover your database by following the instructions at the bottom of the following page : http://banshee.fm/support/faq/
Please ignore my previous comment, it was meant for another bug... Sorry ! Now that I'm here : Which versions of sqlite and mono do you have ?
Banshee 1.7.4 libsqlite3-0 3.7.2-1 libmono-sqlite2.0-cil 2.4.4~svn151842-3 This has been happening for ages, though, with older versions of everything. It's not a recent regression.
http://willthompson.co.uk/misc/bgo-629541.log is a complete log of Banshee running fine for >3 hours and then crashing at the end of a track. I'm seeing a bunch of exceptions from the scrobbling extension; wonder if that's related.
Here's the relevant part of the log. Not sure if the "Saving Metadata to File" is relevant -- might be part of the trigger. [192 Debug 15:53:50.531] Starting - Saving Metadata to File Unhandled Exception: System.ObjectDisposedException: The object was used after being disposed. at System.Threading.WaitHandle.CheckDisposed () [0x00000] in <filename unknown>:0 at System.Threading.WaitHandle.WaitOne () [0x00000] in <filename unknown>:0 at Hyena.Data.Sqlite.HyenaSqliteCommand.WaitIfNotFinished () [0x00000] in /tmp/buildd/banshee-1.9.5/src/Hyena/Hyena.Data.Sqlite/Hyena.Data.Sqlite/HyenaSqliteCommand.cs:171 at Hyena.Data.Sqlite.HyenaSqliteConnection.ProcessQueue () [0x0006d] in /tmp/buildd/banshee-1.9.5/src/Hyena/Hyena.Data.Sqlite/Hyena.Data.Sqlite/HyenaSqliteConnection.cs:437
So the crash is from here: internal void WaitIfNotFinished () { finished_event.WaitOne (); } but this doesn't make sense to me, because finished_event is never disposed in HyenaSqliteCommand.cs. Might be a bug in Will's mono (version 2.6.7 (Debian 2.6.7-5))
If the HyenaSqliteCommand itself was GC'd, then the finished_event could also get GC'd, and its Finalizer does call Dispose. But for the Command to get GC'd, all refs to it would have to be gone -- and so re-using it would be impossible. I'm stumped.
In WaitHandle.cs internal void CheckDisposed () { if (disposed || safe_wait_handle == null) throw new ObjectDisposedException (GetType ().FullName); } So maybe it's not that it's getting GC'd, but that safe_wait_handle is null. It would be null if in EventWaitHandle.cs Handle = NativeEventCalls.CreateEvent_internal (manual, initialState, null, out created); in the Handle setter, it sets safe_wait_handle no matter what (unless an exception was thrown. It's possible an exception is thrown but not logged/doesn't crash Banshee b/c it happens on a background thread -- and that somehow the command gets ran again and triggers this crash. These files are here, btw: http://github.com/mono/mono/tree/master/mcs/class/corlib/System.Threading/
That exception would happen in the construction of the Command though, which would prevent it from ever getting used/referenced I think. So I'm still stumped.
Created attachment 183715 [details] An entirely different backtrace from git master I applied your patch to add more debugging info to the relevant path in HyenaSqliteCommand.cs, and of course now the crash looks completely different. Here's the tail of the log. There's nothing obviously of interest earlier in the log, and there were no messages logged for 5 minutes before the crash (long track!); but I've saved the rest of the log if it's needed. I just used `make run`; forgot to --debug-sql or anything, unfortunately.
Will, that looks like a separate bug; please file it. Please attach the full log here if you can reproduce the System.ObjectDisposedException crash.
Re-posting Will's comment that got lost in the bugzilla server failure (recovered from my bugmail). --- Comment #12 from Will Thompson <will@willthompson.co.uk> 2011-03-24 16:12:42 UTC --- Annoyingly I once again failed to use --debug-sql, but here's a full log of a run of Banshee culminating in System.ObjectDisposedException. It doesn't look like your extra debug logging has added any more information: finished_event.SafeWaitHandle is never null. :( Bugzilla doesn't like the log being over a megabyte. http://willthompson.co.uk/misc/object-disposed-exception.full.log
*** Bug 647478 has been marked as a duplicate of this bug. ***
Same problem here using Ubuntu 11.04 version of banshee. It crashes at the end of the track. Unhandled Exception: System.ObjectDisposedException: The object was used after being disposed. at System.Threading.WaitHandle.CheckDisposed () [0x00000] in <filename unknown>:0 at System.Threading.WaitHandle.WaitOne () [0x00000] in <filename unknown>:0 at Hyena.Data.Sqlite.HyenaSqliteCommand.WaitIfNotFinished () [0x00000] in <filename unknown>:0 at Hyena.Data.Sqlite.HyenaSqliteConnection.ProcessQueue () [0x00000] in <filename unknown>:0
*** Bug 650975 has been marked as a duplicate of this bug. ***
*** Bug 660385 has been marked as a duplicate of this bug. ***
*** Bug 663365 has been marked as a duplicate of this bug. ***
Created attachment 200728 [details] Another log with similar backtrace Here's another log with a similar backtrace. It looks like this may be the trigger: [54 Debug 16:48:48.957] (libbanshee:player) [Gapless] Requesting next track
*** Bug 672236 has been marked as a duplicate of this bug. ***
*** Bug 685336 has been marked as a duplicate of this bug. ***
*** Bug 665222 has been marked as a duplicate of this bug. ***
*** Bug 694531 has been marked as a duplicate of this bug. ***
Dario reproduced it in 2.6.0. Dario, can you tell us if this bug still happens with Gapless option disabled? BTW, the most updated stacktrace with line numbers is from the duped bug: https://bugzilla.gnome.org/attachment.cgi?id=237246
I disabled gapless playback... since I'm unable to reliably reproduce the problem, it's undecidable to know if the bug is still there without gapless If I don't notice it anymore, maybe after a week or 2, I'd say we can just assume that was indeed related to gapless
(In reply to comment #24) > I disabled gapless playback... since I'm unable to reliably reproduce the > problem, it's undecidable to know if the bug is still there without gapless > > If I don't notice it anymore, maybe after a week or 2, I'd say we can just > assume that was indeed related to gapless Sounds good. Can you tell also the mono version you're using?
Mono JIT compiler version 2.10.8.1 (Debian 2.10.8.1-5ubuntu1) Copyright (C) 2002-2011 Novell, Inc, Xamarin, Inc and Contributors. www.mono-project.com TLS: __thread SIGSEGV: altstack Notifications: epoll Architecture: amd64 Disabled: none Misc: softdebug LLVM: supported, not enabled. GC: Included Boehm (with typed GC and Parallel Mark)
*** Bug 696721 has been marked as a duplicate of this bug. ***
I can reproduce the bug reliably on 2.6.0. It has happened to me some 1-10 times per day so it's somewhat common in my experience. Been running my Banshee with gapless mode disabled, and it seems stable. Enabling gapless mode produces crash in ~30 minutes (playing short tracks) so there seems to be pretty clear difference as far as I can tell. Mono JIT compiler version 2.10.8 (tarball Fri Jul 20 23:48:09 UTC 2012) Copyright (C) 2002-2011 Novell, Inc, Xamarin, Inc and Contributors. www.mono-project.com TLS: __thread SIGSEGV: altstack Notifications: epoll Architecture: amd64 Disabled: none Misc: debugger softdebug LLVM: supported, not enabled. GC: Included Boehm (with typed GC and Parallel Mark)
Created attachment 239991 [details] Yet another newer debug trace
Ever since disabling the fuc**** "Gapless" plugin didn't have a single crash (in contrast to a few crashes per day).
a crash every ~30 minutes... strange, I got nowhere close that number but I can confirm as well: since I disabled the gapless playback (it has been a month now) I haven't had a single crash
I have been learning to play guitar so I have these 10-20 second clips from a course in my music library. Playing the shortest tracks makes the bug appear faster. This might help others in testing. Generate a large amount of short tracks with varying contents and play them over.
Thanks for making Banshee! I've had the same exact issue for some time now. It is occasional, happening 1-3 times in an 8-hour period. I will try with gapless playback disabled and report back. Here are my specs: Running Banshee 2.6.0: [Ubuntu 12.04.1 LTS (linux-gnu, x86_64) GStreamer version 0.10.36.0, gapless: True, replaygain: True Mono JIT compiler version 2.10.8.1 (Debian 2.10.8.1-1ubuntu2.2) Unhandled Exception: System.ObjectDisposedException: The object was used after being disposed. at System.Threading.WaitHandle.CheckDisposed () [0x00000] in <filename unknown>:0 at System.Threading.WaitHandle.WaitOne () [0x00000] in <filename unknown>:0 at Hyena.Data.Sqlite.HyenaSqliteCommand.WaitIfNotFinished () [0x00000] in <filename unknown>:0 at Hyena.Data.Sqlite.HyenaSqliteConnection.ProcessQueue () [0x00000] in <filename unknown>:0
(In reply to comment #33) > It is occasional, happening 1-3 times in an 8-hour period. I will try with > gapless playback disabled and report back. I've had no crashes for over a week (366 songs) with gapless playback disabled. I haven't noticed any gap between songs in that time either, so I am happy to keep gapless playback disabled indefinitely. P.S. My machine is upgrading to 2.6.1 as I write this.
Thanks Glen
*** Bug 708626 has been marked as a duplicate of this bug. ***
Banshee is not under active development anymore and had its last code changes more than three years ago. Its codebase has been archived. Closing this report as WONTFIX as part of Bugzilla Housekeeping to reflect reality. Please feel free to reopen this ticket (or rather transfer the project to GNOME Gitlab, as GNOME Bugzilla is being shut down) if anyone takes the responsibility for active development again. See https://gitlab.gnome.org/Infrastructure/Infrastructure/issues/264 for more info.