GNOME Bugzilla – Bug 759292
Buffer free on error leads to infinite recursion in gstv4l2
Last modified: 2017-08-05 16:31:29 UTC
In our application, unplugging the USB camera while capture is in progress sometimes leads to a SIGSEGV. After some looking aroud I came up with the following dgb stack trace (not including everything obviously since it's more than 10000 lines long):
+ Trace 235805
When reproducing with GST_DEBUG=*:8 I get those traces (cropped as well): 0:00:18.890594759 18208 0x10c6ef80 ERROR v4l2allocator gstv4l2allocator.c:1245:gst_v4l2_allocator_qbuf:<v4l2src0:pool:src:allocator> failed queing buffer 3: No such device 0:00:18.890657083 18208 0x10c6ef80 ERROR v4l2bufferpool gstv4l2bufferpool.c:1118:gst_v4l2_buffer_pool_qbuf:<v4l2src0:pool:src> could not queue a buffer 3 0:00:18.890713099 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:1218:default_release_buffer:<v4l2src0:pool:src> released buffer 0xe39fab40 16384 0:00:18.890773102 18208 0x10c6ef80 DEBUG GST_PERFORMANCE gstbufferpool.c:1242:default_release_buffer:<v4l2src0:pool:src> discarding buffer 0xe39fab40: memory tag set 0:00:18.890832900 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:378:do_free_buffer:<v4l2src0:pool:src> freeing buffer 0xe39fab40 (3 left) 0:00:18.890886504 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe39fab40 unref 1->0 0:00:18.890945588 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:631:_gst_buffer_free: finalize 0xe39fab40 0:00:18.890998773 18208 0x10c6ef80 TRACE GST_LOCKING gstminiobject.c:248:gst_mini_object_unlock: unlock 0xe3901df8: state 00010000, access_mode 4 0:00:18.891056956 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe3901df8 unref 1->0 0:00:18.891114069 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:360:gst_mini_object_ref: 0xe3901df8 ref 0->1 0:00:18.891175897 18208 0x10c6ef80 LOG v4l2allocator gstv4l2allocator.c:351:gst_v4l2_allocator_release:<v4l2src0:pool:src:allocator> plane 0 of buffer 3 released 0:00:18.891233601 18208 0x10c6ef80 LOG v4l2allocator gstv4l2allocator.c:367:gst_v4l2_allocator_release:<v4l2src0:pool:src:allocator> buffer 3 released 0:00:18.891292172 18208 0x10c6ef80 DEBUG v4l2bufferpool gstv4l2bufferpool.c:673:gst_v4l2_buffer_pool_resurect_buffer:<v4l2src0:pool:src> A buffer was lost, reallocating it 0:00:18.891367140 18208 0x10c6ef80 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1291:gst_v4l2_buffer_pool_acquire_buffer:<v4l2src0:pool:src> acquire 0:00:18.891422075 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:1090:default_acquire_buffer:<v4l2src0:pool:src> no buffer, trying to allocate 0:00:18.891474402 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstobject.c:254:gst_object_ref:<v4l2src0:pool:src:allocator> 0xe390c0a8 ref 10256->10257 0:00:18.891532954 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:705:gst_buffer_new: new 0xe39fabe0 0:00:18.891587054 18208 0x10c6ef80 TRACE GST_LOCKING gstminiobject.c:188:gst_mini_object_lock: lock 0xe3901df8: state 00000000, access_mode 4 0:00:18.891643706 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:360:gst_mini_object_ref: 0xe3901df8 ref 1->2 0:00:18.891700474 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe3901df8 unref 2->1 0:00:18.891757455 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:330:_memory_add: buffer 0xe39fabe0, idx -1, mem 0xe3901df8 0:00:18.891819899 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:282:do_alloc_buffer:<v4l2src0:pool:src> allocated buffer 3/32, 0xe39fabe0 0:00:18.891877664 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstobject.c:254:gst_object_ref:<v4l2src0:pool:src> 0xe390a060 ref 5128->5129 0:00:18.891936179 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe39fabe0 unref 1->0 0:00:18.891992321 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:360:gst_mini_object_ref: 0xe39fabe0 ref 0->1 0:00:18.892048077 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:616:_gst_buffer_dispose: release 0xe39fabe0 to pool 0xe390a060 0:00:18.892107617 18208 0x10c6ef80 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1369:gst_v4l2_buffer_pool_release_buffer:<v4l2src0:pool:src> release buffer 0xe39fabe0 0:00:18.892166686 18208 0x10c6ef80 LOG v4l2bufferpool gstv4l2bufferpool.c:1074:gst_v4l2_buffer_pool_qbuf:<v4l2src0:pool:src> queuing buffer 3 0:00:18.892240958 18208 0x10c6ef80 ERROR v4l2allocator gstv4l2allocator.c:1245:gst_v4l2_allocator_qbuf:<v4l2src0:pool:src:allocator> failed queing buffer 3: No such device 0:00:18.892303660 18208 0x10c6ef80 ERROR v4l2bufferpool gstv4l2bufferpool.c:1118:gst_v4l2_buffer_pool_qbuf:<v4l2src0:pool:src> could not queue a buffer 3 0:00:18.892361100 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:1218:default_release_buffer:<v4l2src0:pool:src> released buffer 0xe39fabe0 16384 0:00:18.892419261 18208 0x10c6ef80 DEBUG GST_PERFORMANCE gstbufferpool.c:1242:default_release_buffer:<v4l2src0:pool:src> discarding buffer 0xe39fabe0: memory tag set 0:00:18.892478805 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:378:do_free_buffer:<v4l2src0:pool:src> freeing buffer 0xe39fabe0 (3 left) 0:00:18.892532367 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe39fabe0 unref 1->0 0:00:18.892614761 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:631:_gst_buffer_free: finalize 0xe39fabe0 0:00:18.892683008 18208 0x10c6ef80 TRACE GST_LOCKING gstminiobject.c:248:gst_mini_object_unlock: unlock 0xe3901df8: state 00010000, access_mode 4 0:00:18.892742733 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe3901df8 unref 1->0 0:00:18.892800493 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:360:gst_mini_object_ref: 0xe3901df8 ref 0->1 0:00:18.892861484 18208 0x10c6ef80 LOG v4l2allocator gstv4l2allocator.c:351:gst_v4l2_allocator_release:<v4l2src0:pool:src:allocator> plane 0 of buffer 3 released 0:00:18.892918910 18208 0x10c6ef80 LOG v4l2allocator gstv4l2allocator.c:367:gst_v4l2_allocator_release:<v4l2src0:pool:src:allocator> buffer 3 released 0:00:18.892976684 18208 0x10c6ef80 DEBUG v4l2bufferpool gstv4l2bufferpool.c:673:gst_v4l2_buffer_pool_resurect_buffer:<v4l2src0:pool:src> A buffer was lost, reallocating it 0:00:18.893033005 18208 0x10c6ef80 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1291:gst_v4l2_buffer_pool_acquire_buffer:<v4l2src0:pool:src> acquire 0:00:18.893085674 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:1090:default_acquire_buffer:<v4l2src0:pool:src> no buffer, trying to allocate 0:00:18.893139173 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstobject.c:254:gst_object_ref:<v4l2src0:pool:src:allocator> 0xe390c0a8 ref 10258->10259 0:00:18.893201432 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:705:gst_buffer_new: new 0xe39fac80 0:00:18.893254496 18208 0x10c6ef80 TRACE GST_LOCKING gstminiobject.c:188:gst_mini_object_lock: lock 0xe3901df8: state 00000000, access_mode 4 0:00:18.893312122 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:360:gst_mini_object_ref: 0xe3901df8 ref 1->2 0:00:18.893372001 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe3901df8 unref 2->1 0:00:18.893431508 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:330:_memory_add: buffer 0xe39fac80, idx -1, mem 0xe3901df8 0:00:18.893494508 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:282:do_alloc_buffer:<v4l2src0:pool:src> allocated buffer 3/32, 0xe39fac80 0:00:18.893551561 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstobject.c:254:gst_object_ref:<v4l2src0:pool:src> 0xe390a060 ref 5129->5130 0:00:18.893609185 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe39fac80 unref 1->0 0:00:18.893666734 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:360:gst_mini_object_ref: 0xe39fac80 ref 0->1 0:00:18.893724944 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:616:_gst_buffer_dispose: release 0xe39fac80 to pool 0xe390a060 0:00:18.893786691 18208 0x10c6ef80 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1369:gst_v4l2_buffer_pool_release_buffer:<v4l2src0:pool:src> release buffer 0xe39fac80 0:00:18.893846510 18208 0x10c6ef80 LOG v4l2bufferpool gstv4l2bufferpool.c:1074:gst_v4l2_buffer_pool_qbuf:<v4l2src0:pool:src> queuing buffer 3 0:00:18.893921372 18208 0x10c6ef80 ERROR v4l2allocator gstv4l2allocator.c:1245:gst_v4l2_allocator_qbuf:<v4l2src0:pool:src:allocator> failed queing buffer 3: No such device 0:00:18.893997117 18208 0x10c6ef80 ERROR v4l2bufferpool gstv4l2bufferpool.c:1118:gst_v4l2_buffer_pool_qbuf:<v4l2src0:pool:src> could not queue a buffer 3 0:00:18.894055078 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:1218:default_release_buffer:<v4l2src0:pool:src> released buffer 0xe39fac80 16384 0:00:18.894114780 18208 0x10c6ef80 DEBUG GST_PERFORMANCE gstbufferpool.c:1242:default_release_buffer:<v4l2src0:pool:src> discarding buffer 0xe39fac80: memory tag set 0:00:18.894176190 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:378:do_free_buffer:<v4l2src0:pool:src> freeing buffer 0xe39fac80 (3 left) 0:00:18.894232103 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe39fac80 unref 1->0 0:00:18.894290809 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:631:_gst_buffer_free: finalize 0xe39fac80 0:00:18.894343549 18208 0x10c6ef80 TRACE GST_LOCKING gstminiobject.c:248:gst_mini_object_unlock: unlock 0xe3901df8: state 00010000, access_mode 4 0:00:18.894399810 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:440:gst_mini_object_unref: 0xe3901df8 unref 1->0 0:00:18.894458273 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstminiobject.c:360:gst_mini_object_ref: 0xe3901df8 ref 0->1 0:00:18.894532648 18208 0x10c6ef80 LOG v4l2allocator gstv4l2allocator.c:351:gst_v4l2_allocator_release:<v4l2src0:pool:src:allocator> plane 0 of buffer 3 released 0:00:18.894586955 18208 0x10c6ef80 LOG v4l2allocator gstv4l2allocator.c:367:gst_v4l2_allocator_release:<v4l2src0:pool:src:allocator> buffer 3 released 0:00:18.894631154 18208 0x10c6ef80 DEBUG v4l2bufferpool gstv4l2bufferpool.c:673:gst_v4l2_buffer_pool_resurect_buffer:<v4l2src0:pool:src> A buffer was lost, reallocating it 0:00:18.894683331 18208 0x10c6ef80 DEBUG v4l2bufferpool gstv4l2bufferpool.c:1291:gst_v4l2_buffer_pool_acquire_buffer:<v4l2src0:pool:src> acquire 0:00:18.894731410 18208 0x10c6ef80 LOG bufferpool gstbufferpool.c:1090:default_acquire_buffer:<v4l2src0:pool:src> no buffer, trying to allocate 0:00:18.894782971 18208 0x10c6ef80 TRACE GST_REFCOUNTING gstobject.c:254:gst_object_ref:<v4l2src0:pool:src:allocator> 0xe390c0a8 ref 10260->10261 0:00:18.894832417 18208 0x10c6ef80 LOG GST_BUFFER gstbuffer.c:705:gst_buffer_new: new 0xe39fad20 Commenting out line 1129 in gstv4l2bufferpool.c (GST_BUFFER_FLAG_SET (buf, GST_BUFFER_FLAG_TAG_MEMORY);) works around this in the sense that it prevents the app from crashing. Probably introduces a memory leak though.
Created attachment 354639 [details] [review] Block recursive calls to gst_v4l2_buffer_pool_resurect_buffer() I recently encountered this bug as well. I don't know the v4l2 code well enough to fully understand what is going wrong, but the immediate cause is that the group-released signal is triggering a call to gst_v4l2_buffer_pool_resurect_buffer(), which allocates and frees a buffer. The free results in group-released being sent again, so the code recurses infinitely. The simplest solution is just to block reception of the signal while the signal handler is running. This seemed to resolve the problem for me, but I don't know if it is the correct solution. I've attached a patch, can anybody comment on its correctness?
This is a fair workaround, but then you'll leak a buffer, which leaks the pool, hence allocator, hence one device FD, and that will cause troubles. I think it better to merge this patch then to do nothing, yet, to fully fix this, we need to remove the queuing process from the buffer pool, and while at it detach the streaming state from it too.
Can you elaborate on how this will leak a buffer? I'm not sure I follow.
I'm not fully certain if and what would be leaked, I bet this should be verified prior to merging. GST_TRACERS="leaks" GST_DEBUG="GST_TRACER:7" gst-launch-1.0 ...
Unfortunately I'm not exactly sure how to provoke the bad condition when just using a simple gst-launch command, this came originally from a larger application that creates/destroys a bunch of pipelines dynamically. Is it possible to use GST_TRACER on a program like that? I confess I haven't ever used it before.
The tracer works on any program, not just gst-launch.
It looks like the leak tracers were added in 1.9.x. I'm unfortunately stuck back on 1.8.3 in my development environment. I can try to work on pulling things up, but it may take some doing. Is there some other way to easily verify that this does the right thing?
Note that I've started looking at it, and it might be fine. The GstBuffer that could not be queued get unreffed, and the memory will be left unused in the allocator. It should not be leaking it, unless in case the is another bug. It remains unfortunate as the pipeline should post an error, which I don't think is possible in the code path.
I think this can only improve the situation. Thanks. Backport will be done in batch for V4L2 as usual.
commit 52a565803032a68e778ce8c2e1a953909db4e2bd Author: Matt Fischer <matt.fischer@garmin.com> Date: Wed Jun 28 14:05:27 2017 -0500 v4l2: Block recursive calls to resurect_buffer When resurrecting a buffer, the subsequent free call can result in the group-released handler being called again, which causes a recursive loop. This patch blocks the signal handler during the time that it executes, ensuring that the loop will not occur. https://bugzilla.gnome.org/show_bug.cgi?id=759292
Now queued for 1.12.3 Author: Matt Fischer <matt.fischer@garmin.com> Date: Wed Jun 28 14:05:27 2017 -0500 v4l2: Block recursive calls to resurect_buffer When resurrecting a buffer, the subsequent free call can result in the group-released handler being called again, which causes a recursive loop. This patch blocks the signal handler during the time that it executes, ensuring that the loop will not occur. https://bugzilla.gnome.org/show_bug.cgi?id=759292
*** Bug 761703 has been marked as a duplicate of this bug. ***