GNOME Bugzilla – Bug 682239
Crash on GST_PAD_STREAM_UNLOCK (peer) in gst_pad_push()
Last modified: 2013-01-05 15:14:25 UTC
Created attachment 221813 [details] Crash 1 - gdb info I encounter random crashes on GST_PAD_STREAM_UNLOCK (peer) in gst_pad_push(). My environment is quite complex and was already described in #679950. Problems started to appear when I added missing unrefs after releasing adder pad. I've caught problem a few times and backtrace always looks like that:
+ Trace 230702
The context is that I am trying to dynamically unlink part of the pipeline (encapsulated in bin with src ghost pad) that is attached to adder. I do the following: 1. (app thread) Block bin's src ghost pad asynchronously 2. (streaming thread) In async pad block handler: a) unlink bin's src ghost pad from adder's pad b) release adder's pad c) unref adder's pad d) call Idle.add 3. (app thread) In Idle.add handler: a) set bin's state to NULL b) remove bin from pipeline Crash happens in 2b or 2c, I am not sure yet. Unfortunately I was unable to catch such a crash with GST_DEBUG enabled (seems that logging overhead prevents for such coincidence) but I am still trying.
Created attachment 221814 [details] Crash 2 - gdb info
Created attachment 221825 [details] Crash 3 - gdb info
I finally got report with GST_DEBUG enabled. Last logs are copied below. GDB report (named Crash 4) is attached. 2012-08-20 14:35:57.689 [APP APPTHREAD MESG] [Source "automat#5"] Playback finished 2012-08-20 14:35:57.689 [APP APPTHREAD MESG] [Source "automat"] Playback of item #5 has finished playback, shutting down 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] State transition "Element.Base.shutdown": Locking 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] State transition "Element.Base.shutdown": Locked 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] State transition "Element.Base.shutdown": I am in state "attached", calling transition function 2012-08-20 14:35:57.689 [APP APPTHREAD MESG] [Source "automat#5"] Shutting down... 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] Detach: Attempt, type is "shutdown" 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] Setting pending detach type to "shutdown" 2012-08-20 14:35:57.689 [APP APPTHREAD MESG] [Source "automat#5"] Detaching... 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] Setting target state to "detached" 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] Setting current state to "during-detach" 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] On detach begin: Disabling timers 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] Cancelling position interval 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] Cancelling fade out interval 2012-08-20 14:35:57.689 [APP APPTHREAD DEBG] [Source "automat#5"] On detach begin: Trying to fire both next item request & playback finish signals 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] Detach: Not necessary to block output 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] Detach: pipeline pad is not null 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] Detach: unlinking from adder 0:10:46.622190838 3513 0x84a0e00 INFO GST_ELEMENT_PADS gstelement.c:975:gst_element_get_static_pad: found pad source_automat#5_BIN:src 0:10:46.622206051 3513 0x84a0e00 INFO GST_ELEMENT_PADS gstpad.c:1750:gst_pad_unlink: unlinking source_automat#5_BIN:src(0x8827000) and source_automat_adder:sink4(0x8861f18) 0:10:46.622242162 3513 0x84a0e00 INFO GST_ELEMENT_PADS gstpad.c:1795:gst_pad_unlink: unlinked source_automat#5_BIN:src and source_automat_adder:sink4 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] Detach: releasing unnecessary adder pad 0:10:46.622323729 3513 0x84a0e00 INFO GST_ELEMENT_PADS gstelement.c:847:gst_element_remove_pad:<source_automat_adder> removing pad 'sink4' 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] Detach: unref unnecessary adder pad 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] Detach: setting pipeline pad to null 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] Detach: stop playback and remove bin from parent - scheduling in idle 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] State transition "Element.Base.shutdown": Unlocking 2012-08-20 14:35:57.690 [APP APPTHREAD DEBG] [Source "automat#5"] State transition "Element.Base.shutdown": Unlocked 0:10:46.622594283 3513 0xb589a380 WARN collectpads gstcollectpads.c:1421:gst_collect_pads_chain: sink4 got removed from collectpads
Created attachment 221828 [details] Crash 4 - gdb info
Created attachment 221829 [details] Crash 4 - gdb info (correct file uploaded this time)
Can you check the refcount of the pad when it crashes? I'm ready to bet it goes down to 0. Are you certain you hold two refs to the pad when you get to that point? gst_element_release_pad() removes one ref. Anyway, unless you have a simple test case, I'm at least 95% sure that the bug is in the ref handling in your code.
Olivier, thank you for quick reply. What you write stands in opposition to docs: "gst_element_release_request_pad () This does not unref the pad. If the pad was created by using gst_element_get_request_pad(), gst_element_release_request_pad() needs to be followed by gst_object_unref() to free the pad. " I've taken a brief look on the source and there's no unref on pad. Only on peer pad. But I will add refcount check as you suggest and reopen the ticket if problem still will be present.
Hi, I've did some investigation. I am sure that for 95% it is NOT my fault ;) I've run the same code, many times with refcount tracking. When it works OK it results in: 2012-08-21 13:21:53.925 [APP 0x94233b0 DEBG] [Source "test"] Detach: pipeline pad is not null 2012-08-21 13:21:53.925 [APP 0x94233b0 DEBG] [Source "test"] Detach: unlinking from adder 2012-08-21 13:21:53.925 [APP 0x94233b0 DEBG] [Source "test"] Detach: pipeline pad ref count = 3 0:00:25.314535111 4655 0x94233b0 INFO GST_ELEMENT_PADS gstpad.c:1750:gst_pad_unlink: unlinking source_test_BIN:src(0x94209c0) and patchbay_adder:sink1(0x9574198) 0:00:25.314589657 4655 0x94233b0 INFO GST_ELEMENT_PADS gstpad.c:1795:gst_pad_unlink: unlinked source_test_BIN:src and patchbay_adder:sink1 2012-08-21 13:21:53.925 [APP 0x94233b0 DEBG] [Source "test"] Detach: releasing unnecessary adder pad 2012-08-21 13:21:53.925 [APP 0x94233b0 DEBG] [Source "test"] Detach: pipeline pad ref count = 3 0:00:25.314797505 4655 0x94233b0 INFO GST_ELEMENT_PADS gstelement.c:847:gst_element_remove_pad:<patchbay_adder> removing pad 'sink1' 2012-08-21 13:21:53.925 [APP 0x94233b0 DEBG] [Source "test"] Detach: unref unnecessary adder pad 2012-08-21 13:21:53.925 [APP 0x94233b0 DEBG] [Source "test"] Detach: pipeline pad ref count = 2 But sometimes, exactly the same code, in the same environment outputs: 2012-08-21 13:12:39.878 [APP 0x8544950 DEBG] [Source "test"] Detach: pipeline pad is not null 2012-08-21 13:12:39.878 [APP 0x8544950 DEBG] [Source "test"] Detach: unlinking from adder 2012-08-21 13:12:39.878 [APP 0x8544950 DEBG] [Source "test"] Detach: pipeline pad ref count = 4 0:00:28.299488714 4595 0x8544950 INFO GST_ELEMENT_PADS gstpad.c:1750:gst_pad_unlink: unlinking source_test_BIN:src(0x85421c0) and patchbay_adder:sink1(0x86961a0) 0:00:28.299591241 4595 0x8544950 INFO GST_ELEMENT_PADS gstpad.c:1795:gst_pad_unlink: unlinked source_test_BIN:src and patchbay_adder:sink1 2012-08-21 13:12:39.879 [APP 0x8544950 DEBG] [Source "test"] Detach: releasing unnecessary adder pad 2012-08-21 13:12:39.879 [APP 0x8544950 DEBG] [Source "test"] Detach: pipeline pad ref count = 4 0:00:28.300200746 4595 0x85449b0 WARN collectpads gstcollectpads.c:1421:gst_collect_pads_chain: sink1 got removed from collectpads 0:00:28.300296847 4595 0x8544950 INFO GST_ELEMENT_PADS gstelement.c:847:gst_element_remove_pad:<patchbay_adder> removing pad 'sink1' 2012-08-21 13:12:39.879 [APP 0x8544950 DEBG] [Source "test"] Detach: unref unnecessary adder pad 2012-08-21 13:12:39.880 [APP 0x8544950 DEBG] [Source "test"] Detach: pipeline pad ref count = 1 2012-08-21 13:12:39.880 [APP 0x8544950 DEBG] [Source "test"] Detach: setting pipeline pad to null 2012-08-21 13:12:39.880 [GST 0x8544950 CRIT] gst_object_unref: assertion `((GObject *) object)->ref_count > 0' failed 2012-08-21 13:12:39.882 [APP 0x8544950 DEBG] [Source "test"] Detach: stop playback and remove bin from parent - scheduling in idle 2012-08-21 13:12:39.882 [APP APPTHREAD DEBG] [Source "test"] Detach: Stopping playback Obviously, I can add (and I will) some checks to decide whether I should unref or not based on current ref_count, but don't you think that Gst behaviour in such case should be more predictable? Now I am just following the documentation, and in 50% of cases I encounter ref_count error that is related to GStreamer internals.
Could you make a small test case that reproduces the bug?
I'll try.
The case is that when I disabled manual unreffing and so on, everyting works OK, and pads get freed. When I store weak reference to requested pad, so I don't increase it refcount, it has refcount of 2, and during release it decrease to 0. So technically speaking, GStreamer works as expected. The only thing is that in docs there's clearly stated that I should unref that manually, and following that rule causes crashes. I am not sure what is the reason for that.
I don't know what to do about this bug. I don't think we'll want to change anything in 0.10 other than most obvious issues. Perhaps one of the elements with request pads doesn't handle refcounting properly somewhere? Or there's a duplicate pad unref() somewhere that only has an effect at the very end when you try to release your ref?
0.10 is unmaintained now, and we most definitely don't want to make any semantic changes to it how request pad refcounting works. In the absence of a test case or patch, I would suggest we close this bug. Please file a new bug, ideally with a test case to reproduce it, if you still have problems with GStreamer 1.x (the request pad handling has changed a little there).