clementine-player / Clementine

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

Crash at the end of a track if the file behind the next track has been removed / doesn't exist #7233

Open raphj opened 1 year ago

raphj commented 1 year ago

Before posting

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

System information

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

Expected behaviour / actual behaviour

Steps to reproduce the problem (only for bugs)

Note: the removed file had a .m4a extension Note: also present in the openSUSE Tumbleweed package.

Investigation

Running Clementine in Valgrind, the following can be seen at the moment of the crash

20:49:57.344 ERROR GstEnginePipeline:686            1 "../plugins/elements/gstfilesrc.c(553): gst_file_src_start (): /GstPipeline:audio-pipeline-1/GstURIDecodeBin:uridecodebin-20/GstFileSrc:source:"
20:49:57.351 ERROR GstEnginePipeline:686            1 "No such file \"/home/xxx/xxx/xxx/xxx.m4a
20:49:57.354 ERROR GstEnginePipeline:686            1 "../libs/gst/base/gstbasesrc.c(3556): gst_base_src_start (): /GstPipeline:audio-pipeline-1/GstURIDecodeBin:uridecodebin-20/GstFileSrc:source:"
20:49:57.354 ERROR GstEnginePipeline:686            1 "Failed to start"
20:49:57.359 ERROR GstEnginePipeline:686            1 "../plugins/elements/gstfilesrc.c(553): gst_file_src_start (): /GstPipeline:audio-pipeline-1/GstURIDecodeBin:uridecodebin-20/GstFileSrc:source:"
20:49:57.359 ERROR GstEnginePipeline:686            1 "No such file \"/xxx/xxx/xxx/xxx/xxx.m4a\""
20:49:57.360 ERROR GstEnginePipeline:686            1 "../libs/gst/base/gstbasesrc.c(3556): gst_base_src_start (): /GstPipeline:audio-pipeline-1/GstURIDecodeBin:uridecodebin-20/GstFileSrc:source:"
20:49:57.361 ERROR GstEnginePipeline:686            1 "Failed to start"
20:49:57.366 WARN  GstEngine:719                    Gstreamer error: "Ressource introuvable."

(clementine:17665): GStreamer-CRITICAL **: 20:49:57.439: 
Trying to dispose element typefind, but it is in PLAYING instead of the NULL state.
You need to explicitly set elements to the NULL state before
dropping the final reference, to allow them to clean up.
This problem may also be caused by a refcounting bug in the
application or some element.

(clementine:17665): GStreamer-CRITICAL **: 20:49:57.445: 
Trying to dispose element decodebin1, but it is in PLAYING instead of the NULL state.
You need to explicitly set elements to the NULL state before
dropping the final reference, to allow them to clean up.
This problem may also be caused by a refcounting bug in the
application or some element.

(clementine:17665): GStreamer-CRITICAL **: 20:49:57.445: 
Trying to dispose element source, but it is in PLAYING instead of the NULL state.
You need to explicitly set elements to the NULL state before
dropping the final reference, to allow them to clean up.
This problem may also be caused by a refcounting bug in the
application or some element.

(clementine:17665): GStreamer-CRITICAL **: 20:49:57.446: 
Trying to dispose element uridecodebin-19, but it is in PLAYING instead of the NULL state.
You need to explicitly set elements to the NULL state before
dropping the final reference, to allow them to clean up.
This problem may also be caused by a refcounting bug in the
application or some element.

==22990== Thread 1:
==22990== Invalid read of size 8
==22990==    at 0x5D440D4: g_type_check_instance_cast (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x25D7CCF2: ??? (in /usr/lib64/gstreamer-1.0/libgstplayback.so)
==22990==    by 0x25D74FD8: ??? (in /usr/lib64/gstreamer-1.0/libgstplayback.so)
==22990==    by 0x5D249D4: g_object_unref (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x5FAF35D: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5DBE397: g_list_foreach (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5DBE3BA: g_list_free_full (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5FC9D94: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9E98C: gst_element_change_state (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9E9D0: gst_element_change_state (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9EFB2: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0xB1343F: GstEnginePipeline::~GstEnginePipeline() (gstenginepipeline.cpp:527)
==22990==  Address 0x27eee0b0 is 48 bytes inside a block of size 680 free'd
==22990==    at 0x484717B: free (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==22990==    by 0x5DC8C88: g_free (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5DE1C5F: g_slice_free1 (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5D42B65: g_type_free_instance (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x5F79F0F: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F75265: gst_bin_remove (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F759B2: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5D248DA: g_object_unref (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x5FAF35D: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5DBE397: g_list_foreach (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5DBE3BA: g_list_free_full (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5FC9D94: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==  Block was alloc'd at
==22990==    at 0x48447B4: malloc (in /usr/libexec/valgrind/vgpreload_memcheck-amd64-linux.so)
==22990==    by 0x5DC8B78: g_malloc (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5DE1511: g_slice_alloc (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5DE1B98: g_slice_alloc0 (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5D42774: g_type_create_instance (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x5D254AF: ??? (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x5D26AB7: g_object_new_with_properties (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x5FA0FB8: gst_element_factory_create_with_properties (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5FA1819: gst_element_factory_make_with_properties (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x25D7D319: ??? (in /usr/lib64/gstreamer-1.0/libgstplayback.so)
==22990==    by 0x25D7F178: ??? (in /usr/lib64/gstreamer-1.0/libgstplayback.so)
==22990==    by 0x5F9E98C: gst_element_change_state (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990== 
==22990== Invalid read of size 8
==22990==    at 0x5D440E3: g_type_check_instance_cast (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x25D7CCF2: ??? (in /usr/lib64/gstreamer-1.0/libgstplayback.so)
==22990==    by 0x25D74FD8: ??? (in /usr/lib64/gstreamer-1.0/libgstplayback.so)
==22990==    by 0x5D249D4: g_object_unref (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x5FAF35D: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5DBE397: g_list_foreach (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5DBE3BA: g_list_free_full (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5FC9D94: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9E98C: gst_element_change_state (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9E9D0: gst_element_change_state (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9EFB2: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0xB1343F: GstEnginePipeline::~GstEnginePipeline() (gstenginepipeline.cpp:527)
==22990==  Address 0xaaaaaaaaaaaaaaaa is not stack'd, malloc'd or (recently) free'd
==22990== 
==22990== 
==22990== Process terminating with default action of signal 11 (SIGSEGV): dumping core
==22990==  General Protection Fault
==22990==    at 0x5D440E3: g_type_check_instance_cast (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x25D7CCF2: ??? (in /usr/lib64/gstreamer-1.0/libgstplayback.so)
==22990==    by 0x25D74FD8: ??? (in /usr/lib64/gstreamer-1.0/libgstplayback.so)
==22990==    by 0x5D249D4: g_object_unref (in /usr/lib64/libgobject-2.0.so.0.7400.1)
==22990==    by 0x5FAF35D: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5DBE397: g_list_foreach (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5DBE3BA: g_list_free_full (in /usr/lib64/libglib-2.0.so.0.7400.1)
==22990==    by 0x5FC9D94: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9E98C: gst_element_change_state (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9E9D0: gst_element_change_state (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0x5F9EFB2: ??? (in /usr/lib64/libgstreamer-1.0.so.0.2004.0)
==22990==    by 0xB1343F: GstEnginePipeline::~GstEnginePipeline() (gstenginepipeline.cpp:527)
==22990== 
==22990== HEAP SUMMARY:
==22990==     in use at exit: 47,341,023 bytes in 259,168 blocks
==22990==   total heap usage: 4,300,158 allocs, 4,040,990 frees, 757,016,339 bytes allocated
==22990== 
==22990== LEAK SUMMARY:
==22990==    definitely lost: 27,704 bytes in 37 blocks
==22990==    indirectly lost: 17,788 bytes in 519 blocks
==22990==      possibly lost: 10,886,187 bytes in 3,878 blocks
==22990==    still reachable: 36,199,280 bytes in 253,685 blocks
==22990==                       of which reachable via heuristic:
==22990==                         newarray           : 45,264 bytes in 244 blocks
==22990==                         multipleinheritance: 246,480 bytes in 284 blocks
==22990==         suppressed: 32 bytes in 1 blocks
==22990== Rerun with --leak-check=full to see details of leaked memory
==22990== 
==22990== For lists of detected and suppressed errors, rerun with: -s
==22990== ERROR SUMMARY: 3 errors from 3 contexts (suppressed: 0 from 0)
[1]    22990 segmentation fault (core dumped)  valgrind ./clementine
raphj commented 1 year ago

When running clementine in rr, it is possible to get the trace at the time clementine segfaults:

Thread 1 received signal SIGSEGV, Segmentation fault.
g_type_check_instance_cast (type_instance=type_instance@entry=0x3f50120, iface_type=iface_type@entry=0x50 [GObject]) at ../gobject/gtype.c:4127
4127              node = lookup_type_node_I (type_instance->g_class->g_type);
(rr) where
#0  g_type_check_instance_cast (type_instance=type_instance@entry=0x3f50120, iface_type=iface_type@entry=0x50 [GObject]) at ../gobject/gtype.c:4127
#1  0x00007fa631f42cf3 in remove_decoders (bin=0x35c4080 [GstURIDecodeBin], force=1) at ../gst/playback/gsturidecodebin.c:1693
#2  0x00007fa631f3afd9 in gst_uri_decode_bin_finalize (obj=0x35c4080 [GstURIDecodeBin]) at ../gst/playback/gsturidecodebin.c:769
#3  0x00007fa66b7799d5 in g_object_unref (_object=<optimized out>) at ../gobject/gobject.c:3909
#4  g_object_unref (_object=0x35c4080) at ../gobject/gobject.c:3784
#5  0x00007fa66b4d035e in _gst_message_free (message=0x46de9a0 [GstMessage]) at ../gst/gstmessage.c:213
#6  0x00007fa66b676398 in g_list_foreach (list=<optimized out>, list@entry=0x3630140 = {...}, func=0x7fa66b49b240 <gst_message_unref.lto_priv>, user_data=user_data@entry=0x0) at ../glib/glist.c:1092
#7  0x00007fa66b6763bb in g_list_free_full (list=0x3630140 = {...}, free_func=<optimized out>) at ../glib/glist.c:246
#8  0x00007fa66b4ead95 in gst_pipeline_change_state (element=0x7fa62c0271b0 [GstPipeline], transition=<optimized out>) at ../gst/gstpipeline.c:576
#9  0x00007fa66b4bf98d in gst_element_change_state (element=element@entry=0x7fa62c0271b0 [GstPipeline], transition=GST_STATE_CHANGE_READY_TO_NULL) at ../gst/gstelement.c:3083
#10 0x00007fa66b4bf840 in gst_element_continue_state (element=element@entry=0x7fa62c0271b0 [GstPipeline], ret=ret@entry=GST_STATE_CHANGE_SUCCESS) at ../gst/gstelement.c:2791
#11 0x00007fa66b4bf9d1 in gst_element_change_state (element=element@entry=0x7fa62c0271b0 [GstPipeline], transition=transition@entry=GST_STATE_CHANGE_PAUSED_TO_READY) at ../gst/gstelement.c:3122
#12 0x00007fa66b4bffb3 in gst_element_set_state_func (element=0x7fa62c0271b0 [GstPipeline], state=GST_STATE_NULL) at ../gst/gstelement.c:3037
#13 0x0000000000b13440 in GstEnginePipeline::~GstEnginePipeline() (this=0x35aa110, __in_chrg=<optimized out>) at /home/raph/dl/Clementine/src/engines/gstenginepipeline.cpp:527
#14 0x0000000000b135e4 in GstEnginePipeline::~GstEnginePipeline() (this=0x35aa110, __in_chrg=<optimized out>) at /home/raph/dl/Clementine/src/engines/gstenginepipeline.cpp:542
#15 0x0000000000b0fbd8 in std::_Sp_counted_ptr<GstEnginePipeline*, (__gnu_cxx::_Lock_policy)2>::_M_dispose() (this=0x35bafd0) at /usr/include/c++/12/bits/shared_ptr_base.h:428
#16 0x0000000000a94759 in std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release() (this=0x35bafd0) at /usr/include/c++/12/bits/shared_ptr_base.h:346
#17 0x0000000000a95c4b in std::__shared_count<(__gnu_cxx::_Lock_policy)2>::~__shared_count() (this=0x7ffe48df8938, __in_chrg=<optimized out>) at /usr/include/c++/12/bits/shared_ptr_base.h:1071
#18 0x0000000000b085ae in std::__shared_ptr<GstEnginePipeline, (__gnu_cxx::_Lock_policy)2>::~__shared_ptr() (this=0x7ffe48df8930, __in_chrg=<optimized out>) at /usr/include/c++/12/bits/shared_ptr_base.h:1524
#19 0x0000000000b08b1b in std::__shared_ptr<GstEnginePipeline, (__gnu_cxx::_Lock_policy)2>::reset() (this=0x2279d70) at /usr/include/c++/12/bits/shared_ptr_base.h:1642
#20 0x0000000000b0668a in GstEngine::HandlePipelineError(int, QString const&, int, int) (this=0x2279cb0, pipeline_id=1, message=..., domain=2616, error_code=3) at /home/raph/dl/Clementine/src/engines/gstengine.cpp:732
#21 0x0000000000d78c2b in GstEngine::qt_static_metacall(QObject*, QMetaObject::Call, int, void**) (_o=0x2279cb0, _c=QMetaObject::InvokeMetaMethod, _id=16, _a=0x7fa65c02b510) at /home/raph/dl/Clementine/bin/src/engines/moc_gstengine.cpp:221
#22 0x00007fa66c107c40 in QObject::event(QEvent*) (this=0x2279cb0, e=0x3428460) at kernel/qobject.cpp:1347
#23 0x00007fa66a9a53fe in QApplicationPrivate::notify_helper(QObject*, QEvent*) (this=<optimized out>, receiver=0x2279cb0, e=0x3428460) at kernel/qapplication.cpp:3637
#24 0x00007fa66c0dc128 in QCoreApplication::notifyInternal2(QObject*, QEvent*) (receiver=0x2279cb0, event=0x3428460) at kernel/qcoreapplication.cpp:1064
#25 0x00007fa66c0df0c1 in QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) (receiver=0x0, event_type=0, data=0x1fc3ab0) at kernel/qcoreapplication.cpp:1821
#26 0x00007fa66c134353 in postEventSourceDispatch(GSource*, GSourceFunc, gpointer) (s=0x20c7450) at kernel/qeventdispatcher_glib.cpp:277
#27 0x00007fa66b67aa90 in g_main_dispatch (context=0x1fd6d80) at ../glib/gmain.c:3444
#28 g_main_context_dispatch (context=context@entry=0x1fd6d80) at ../glib/gmain.c:4162
#29 0x00007fa66b67ae48 in g_main_context_iterate (context=context@entry=0x1fd6d80, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/gmain.c:4238
#30 0x00007fa66b67aedc in g_main_context_iteration (context=0x1fd6d80, may_block=1) at ../glib/gmain.c:4303
#31 0x00007fa66c133b56 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) (this=0x20d7ac0, flags=...) at kernel/qeventdispatcher_glib.cpp:423
#32 0x00007fa66c0dab9b in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) (this=this@entry=0x7ffe48df8e00, flags=..., flags@entry=...) at ../../include/QtCore/../../src/corelib/global/qflags.h:69
#33 0x00007fa66c0e2d06 in QCoreApplication::exec() () at ../../include/QtCore/../../src/corelib/global/qflags.h:121
#34 0x0000000000a685ed in main(int, char**) (argc=1, argv=0x7ffe48df9938) at /home/raph/dl/Clementine/src/main.cpp:478
(rr) 
raphj commented 1 year ago

I spent the evening a a part of the night studying this crash.

This seems to be caused by the fact that

https://github.com/clementine-player/Clementine/blob/dfeb1182f97cf8fc2625523d9a6166a9e20f7e96/src/engines/gstengine.cpp#L732

Resetting this shared_pointer calls GstEnginePipeline::~GstEnginePipeline and GstPipelineBase::GstPipelineBase, which both call gst_element_set_state(pipeline_, GST_STATE_NULL);. First, GStreamer does not seem to like that the pipeline state is set to GST_STATE_NULL twice, which seems to cause the above crash. Guarding these calls by something like

if (gst_element_get_state(pipeline_, &s, &sp, GST_SECOND) !=
      GST_STATE_CHANGE_FAILURE && s != GST_STATE_NULL)

Makes this crash go away, but Clementine crashes later anyway, in GstEnginePipeline::HandoffCallback, which is the callback set at https://github.com/clementine-player/Clementine/blob/dfeb1182f97cf8fc2625523d9a6166a9e20f7e96/src/engines/gstenginepipeline.cpp#L323

Which leads me to believe that the pipeline still seems to try to live its life and do things even after an error occurred, or that somebody is still using it, maybe GstEngine itself. An error and then a NULL state is not a guarantee that the pipeline is completely dead.

I therefore believe that getting rid of a pipeline because there was an error is not enough. If done, we must ensure that it is really gotten rid of completely, we entirely kill it and don't attempt to use it anymore.

In my case, removing the reset call solves the issue. No crash anymore. The issue is that this call has always been there. It was introduced in commit c7f4a091ed introducing GStreamer in Clementine (the commit is called "Let's give GStreamer another try... ", title with which I can only sympathize...)

https://github.com/clementine-player/Clementine/blob/c7f4a091ed1055a01a1278da571fbe32d67171c0/src/engines/gstengine.cpp#L819

So, either it was added under the assumption that a pipeline that got an error is broken and needs to be destroyed (which is false), or because an issue showed up when not destroying it (which is apparently not a complete solution).

I was tempted by detecting this specific case and only skipping this call when a file is not found, but unfortunately, the error_code I get in this case is: GST_CORE_ERROR_NOT_IMPLEMENTED (3). Not very specific, informative, helpful. I'm not sure I'll only handle this specific case.

If I understand what I observed correctly, I see two possible solutions (fixes):

  1. we remove this call. It makes Clementine crash anyway. We pray that it actually makes Clementine crash less often and that it does not break Clementine under other GStreamer error conditions.
  2. we don't remove this call. Something is currently missing to handle this: we must make sure to clean up an pipeline that produced an error properly and completely, and we replace it by a new pipeline. I won't be able to handle that by myself, I'm not knowledgeable in both this part of Clementine and in GStreamer.

@davidsansome do you have any insight on the matter? Do you remember why you introduced this call back then?

Anyone else? WDYT?