After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 688824 - queue: Dropping sticky events on flush without resending them later
queue: Dropping sticky events on flush without resending them later
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gstreamer (core)
1.x
Other Linux
: Normal critical
: 1.1.1
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2012-11-21 17:54 UTC by Jens Georg
Modified: 2013-05-27 11:06 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
Valgrind log (80.70 KB, application/x-xz)
2012-11-22 07:04 UTC, Jens Georg
  Details
New valgrind file (17.58 KB, application/x-xz)
2013-05-02 12:29 UTC, Jens Georg
  Details
backtrace (5.21 KB, text/plain)
2013-05-03 09:32 UTC, Jens Georg
  Details
0001-queue-queue2-multiqueue-When-flushing-make-sure-to-n.patch (10.22 KB, patch)
2013-05-09 12:12 UTC, Sebastian Dröge (slomo)
committed Details | Review

Description Jens Georg 2012-11-21 17:54:53 UTC
When trying to play back http://download.blender.org/peach/trailer/trailer_400p.ogg every now and then I get a crash in theora_handle_type_packet (thread 18 in the bt):

Thread 25 (Thread 0x7fffb53f5700 (LWP 25413))

  • #0 malloc
    from /opt/gnome2/lib64/libglib-2.0.so.0
  • #1 g_malloc
    at gmem.c line 159
  • #2 g_source_set_callback
    at gmain.c line 1507
  • #3 soup_add_completion_reffed
    at soup-misc.c line 124
  • #4 do_idle_run_queue
    at soup-session-async.c line 363
  • #5 gst_soup_http_src_session_unpause_message
    at gstsouphttpsrc.c line 611
  • #6 gst_soup_http_src_create
    at gstsouphttpsrc.c line 1162
  • #7 gst_base_src_get_range
    at gstbasesrc.c line 2355
  • #8 gst_base_src_loop
    at gstbasesrc.c line 2600
  • #9 gst_task_func
    at gsttask.c line 316
  • #10 g_thread_pool_thread_proxy
    at gthreadpool.c line 309
  • #11 g_thread_proxy
    at gthread.c line 797
  • #12 start_thread
    at pthread_create.c line 308
  • #13 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 112
  • #14 ??

Thread 21 (Thread 0x7fffb5bf6700 (LWP 25400))

  • #0 gst_memory_init
    at gstmemory.c line 114
  • #1 _default_mem_init
    at gstallocator.c line 367
  • #2 _default_mem_new_block
    at gstallocator.c line 430
  • #3 gst_buffer_new_allocate
    at gstbuffer.c line 621
  • #4 gst_ogg_demux_chain_peer
    at gstoggdemux.c line 637
  • #5 gst_ogg_demux_push_queued_buffers
    at gstoggdemux.c line 2553
  • #6 gst_ogg_demux_activate_chain
    at gstoggdemux.c line 2576
  • #7 gst_ogg_pad_submit_packet
    at gstoggdemux.c line 1058
  • #8 gst_ogg_pad_stream_out
    at gstoggdemux.c line 1114
  • #9 gst_ogg_pad_submit_page
    at gstoggdemux.c line 1749
  • #10 gst_ogg_demux_handle_page
    at gstoggdemux.c line 4114
  • #11 gst_ogg_demux_chain
    at gstoggdemux.c line 4182
  • #12 gst_pad_chain_data_unchecked
    at gstpad.c line 3654
  • #13 gst_pad_push_data
    at gstpad.c line 3871
  • #14 gst_pad_chain_data_unchecked
    at gstpad.c line 3654
  • #15 gst_pad_push_data
    at gstpad.c line 3871
  • #16 gst_proxy_pad_chain_default
    at gstghostpad.c line 128
  • #17 gst_pad_chain_data_unchecked
    at gstpad.c line 3654
  • #18 gst_pad_push_data
    at gstpad.c line 3871
  • #19 gst_queue2_push_one
    at gstqueue2.c line 2448
  • #20 gst_queue2_loop
    at gstqueue2.c line 2541
  • #21 gst_task_func
    at gsttask.c line 316
  • #22 g_thread_pool_thread_proxy
    at gthreadpool.c line 309
  • #23 g_thread_proxy
    at gthread.c line 797
  • #24 start_thread
    at pthread_create.c line 308
  • #25 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 112
  • #26 ??

Thread 18 (Thread 0x7fffc288f700 (LWP 25397))

  • #0 theora_handle_type_packet
    at gsttheoradec.c line 409
  • #1 theora_handle_header_packet
    at gsttheoradec.c line 539
  • #2 theora_dec_decode_buffer
    at gsttheoradec.c line 788
  • #3 theora_dec_handle_frame
    at gsttheoradec.c line 812
  • #4 gst_video_decoder_decode_frame
    at gstvideodecoder.c line 2665
  • #5 gst_video_decoder_have_frame
    at gstvideodecoder.c line 2602
  • #6 gst_video_decoder_chain_forward
    at gstvideodecoder.c line 1713
  • #7 gst_video_decoder_chain
    at gstvideodecoder.c line 1957
  • #8 gst_pad_chain_data_unchecked
    at gstpad.c line 3654
  • #9 gst_pad_push_data
    at gstpad.c line 3871
  • #10 gst_single_queue_push_one
    at gstmultiqueue.c line 1057
  • #11 gst_multi_queue_loop
    at gstmultiqueue.c line 1303
  • #12 gst_task_func
    at gsttask.c line 316
  • #13 g_thread_pool_thread_proxy
    at gthreadpool.c line 309
  • #14 g_thread_proxy
    at gthread.c line 797
  • #15 start_thread
    at pthread_create.c line 308
  • #16 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 112
  • #17 ??

Thread 17 (Thread 0x7fffc3998700 (LWP 25396))

  • #0 _default_mem_new_block
    at gstallocator.c line 410
  • #1 gst_buffer_new_allocate
    at gstbuffer.c line 621
  • #2 gst_base_src_default_alloc
    at gstbasesrc.c line 1385
  • #3 gst_base_src_default_create
    at gstbasesrc.c line 1423
  • #4 gst_base_src_get_range
    at gstbasesrc.c line 2355
  • #5 gst_base_src_loop
    at gstbasesrc.c line 2600
  • #6 gst_task_func
    at gsttask.c line 316
  • #7 g_thread_pool_thread_proxy
    at gthreadpool.c line 309
  • #8 g_thread_proxy
    at gthread.c line 797
  • #9 start_thread
    at pthread_create.c line 308
  • #10 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 112
  • #11 ??

Thread 1 (Thread 0x7ffff7fb7800 (LWP 25343))

  • #0 __lll_lock_wait_private
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S line 93
  • #1 _L_lock_3549
    at malloc.c line 5209
  • #2 _int_free
    at malloc.c line 4031
  • #3 array_free
    at garray.c line 366
  • #4 gst_structure_free
    at gststructure.c line 376
  • #5 _gst_message_free
    at gstmessage.c line 199
  • #6 gst_message_unref
    at ../gst/gstmessage.h line 332
  • #7 gst_bus_source_dispatch
    at gstbus.c line 774
  • #8 g_main_dispatch
    at gmain.c line 2715
  • #9 g_main_context_dispatch
    at gmain.c line 3219
  • #10 g_main_context_iterate
    at gmain.c line 3290
  • #11 g_main_context_iterate
    at gmain.c line 3227
  • #12 g_main_loop_run
    at gmain.c line 3484
  • #13 rygel_main_run
    at /home/jens/Source/rygel/src/rygel/rygel-main.vala line 81
  • #14 rygel_main_main
    at /home/jens/Source/rygel/src/rygel/rygel-main.vala line 290
  • #15 main
    at /home/jens/Source/rygel/src/rygel/rygel-main.vala line 263

Comment 1 Jens Georg 2012-11-21 17:56:37 UTC
Every now and then meaning about 1 out of 5 attempts.
Comment 2 Tim-Philipp Müller 2012-11-21 21:44:08 UTC
No crashes here, any chance you could get a valgrind trace as well?

What 1.x version is this with exactly? (gst-inspect-1.0 theoradec | grep Version)
Comment 3 Jens Georg 2012-11-22 06:46:01 UTC
Sorry, just realiyed that theora is in base, not good.

Version is 1.1.0.1,

git sha 15ee41dfc9dd4d3dc80cc0a6d2f332aa59284ce2 on gst-plugins-base.
Comment 4 Jens Georg 2012-11-22 07:04:11 UTC
Created attachment 229618 [details]
Valgrind log
Comment 5 Tim-Philipp Müller 2013-01-05 18:57:14 UTC
Do you have a test case that does not involve rygel?

Or maybe a valgrind run that does not have this in it:

==4104== Invalid write of size 4
==4104==    at 0x5FC8EFC: g_main_context_dispatch (gmain.c:2668)
==4104==    by 0x5FC92EF: g_main_context_iterate.isra.25 (gmain.c:3290)
==4104==    by 0x5FC96E9: g_main_loop_run (gmain.c:3484)
==4104==    by 0x405E8C: rygel_main_run (rygel-main.vala:81)
==4104==    by 0x40857C: rygel_main_main (rygel-main.vala:290)
==4104==    by 0x4086AD: main (rygel-main.vala:263)
==4104==  Address 0xed7a35c is 44 bytes inside a block of size 96 free'd
==4104==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==4104==    by 0x5FC6973: g_source_unref_internal (gmain.c:1839)
==4104==    by 0x6D0BDC0: soup_message_io_stop (soup-message-io.c:144)
==4104==    by 0x6D0BE13: soup_message_io_cleanup (soup-message-io.c:100)
==4104==    by 0x6D0C066: soup_message_io_finished (soup-message-io.c:163)
==4104==    by 0x6D0D4EF: io_run (soup-message-io.c:911)
==4104==    by 0x5FC8FA2: g_main_context_dispatch (gmain.c:2715)
==4104==    by 0x5FC92EF: g_main_context_iterate.isra.25 (gmain.c:3290)
==4104==    by 0x5FC96E9: g_main_loop_run (gmain.c:3484)
==4104==    by 0x405E8C: rygel_main_run (rygel-main.vala:81)
==4104==    by 0x40857C: rygel_main_main (rygel-main.vala:290)
==4104==    by 0x4086AD: main (rygel-main.vala:263)


Can you reproduce it with gst-launch-1.0 somehow?
Comment 6 Jens Georg 2013-01-07 13:54:14 UTC
I'll try.
Comment 7 Tobias Mueller 2013-05-02 11:30:19 UTC
Jens Georg, any news here?
Comment 8 Jens Georg 2013-05-02 12:29:31 UTC
Created attachment 243036 [details]
New valgrind file
Comment 9 Sebastian Dröge (slomo) 2013-05-03 09:08:58 UTC
Can you get a valgrind log with debug symbols for gst-plugins-base (and ideally gstreamer, glib, libc, etc) installed? The latest debug log only gives the function names, not exactly where things go wrong
Comment 10 Jens Georg 2013-05-03 09:26:51 UTC
Weird. Have them installed
Comment 11 Jens Georg 2013-05-03 09:32:47 UTC
Created attachment 243155 [details]
backtrace

Backtrace with line numbers from within GDB
Comment 12 Sebastian Dröge (slomo) 2013-05-03 11:07:18 UTC
Yeah, dec->input_state is not set at that point yet.
Comment 13 Sebastian Dröge (slomo) 2013-05-03 11:08:50 UTC
Which means that the decoder got no caps yet. Either that shouldn't happen, or we should reconstruct the caps/input state in that function.
Comment 14 Sebastian Dröge (slomo) 2013-05-04 11:33:02 UTC
Jens, can you get a debug log with GST_DEBUG=6 for this?
Comment 15 Jens Georg 2013-05-04 11:56:39 UTC
No. Apparently this changes some timing so it never happens with GST_DEBUG=6. However, I noticed that I never mentioned that I'm actually meant playback via HTTP, sorry.

I can reproduce it with

gst-launch-1.0 playbin uri=http://download.blender.org/peach/trailer/trailer_400p.ogg
Comment 16 Sebastian Dröge (slomo) 2013-05-06 15:27:03 UTC
<slomo> phako: your logs are from rygel, not gst-launch. and the multiqueue-5 log looks interesting, there are flush-start/stop events for some reason
<slomo> phako: any idea where they could come from? i think there they could drop the caps event from the queue ;)
<slomo> phako: so for some reason there are flush events while stream-start,caps,etc events are in the queue but not forwarded yet. the queue is flushed, the events get lost, downstream only gets the segment event that followed the flush

So what must be done here is to not flush sticky events from the queues that wouldn't be flushed from the pads by flush-stop either.
Comment 17 Sebastian Dröge (slomo) 2013-05-09 12:12:27 UTC
Created attachment 243685 [details] [review]
0001-queue-queue2-multiqueue-When-flushing-make-sure-to-n.patch

Does this help?
Comment 18 Jens Georg 2013-05-09 15:58:07 UTC
It seems to help rygel, but gst-launch still crashes


Thread 4 (Thread 0x7fa37cbaa700 (LWP 27830))

  • #0 nanosleep
    at ../sysdeps/unix/syscall-template.S line 81
  • #1 g_usleep
    at gtimer.c line 261
  • #2 fault_spin
    at gst-launch.c line 109
  • #3 fault_handler_sighandler
    at gst-launch.c line 90
  • #4 <signal handler called>
  • #5 theora_handle_type_packet
    at gsttheoradec.c line 411
  • #6 theora_handle_header_packet
    at gsttheoradec.c line 541
  • #7 theora_dec_decode_buffer
    at gsttheoradec.c line 792
  • #8 theora_dec_handle_frame
    at gsttheoradec.c line 816
  • #9 gst_video_decoder_decode_frame
    at gstvideodecoder.c line 2744
  • #10 gst_video_decoder_have_frame
    at gstvideodecoder.c line 2676
  • #11 gst_video_decoder_parse_available
    at gstvideodecoder.c line 943
  • #12 gst_video_decoder_chain_forward
    at gstvideodecoder.c line 1762
  • #13 gst_video_decoder_chain
    at gstvideodecoder.c line 2003
  • #14 gst_pad_chain_data_unchecked
    at gstpad.c line 3706
  • #15 gst_pad_push_data
    at gstpad.c line 3934
  • #16 gst_pad_push
    at gstpad.c line 4037
  • #17 gst_single_queue_push_one
    at gstmultiqueue.c line 1057
  • #18 gst_multi_queue_loop
    at gstmultiqueue.c line 1303
  • #19 gst_task_func
    at gsttask.c line 316
  • #20 g_thread_pool_thread_proxy
    at gthreadpool.c line 309
  • #21 g_thread_proxy
    at gthread.c line 798
  • #22 start_thread
    at pthread_create.c line 311
  • #23 clone
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S line 113

	Inferior 1 [process 27825] will be detached.

Quit anyway? (y or n) Detaching from program: /opt/rygel-stable/bin/gst-launch-1.0, process 27825
Comment 19 Jens Georg 2013-05-09 16:01:58 UTC
Also, it seems to take longer now to reproduce the bug, approx. 1 out of 20 tries.
Comment 20 Jens Georg 2013-05-11 17:25:28 UTC
Could it be that this patch makes GstDiscoverer really slow?
Comment 21 Sebastian Dröge (slomo) 2013-05-12 07:35:47 UTC
I wouldn't know why :) Could you try to get debug logs of discoverer, and also of the crash again?
Comment 22 Jens Georg 2013-05-13 07:24:47 UTC
With this patch it's not possible to get it crashing at any meaningful loglevel :(

I'll do some more checks on the discoverer thing, might be that it's master and not just this patch alone.
Comment 23 Sebastian Dröge (slomo) 2013-05-22 07:34:06 UTC
Also see bug #700806 , which is yet another problem of flushes dropping sticky events that it shouldn't drop


Any news on this Jens? Any new observations?
Comment 24 Sebastian Dröge (slomo) 2013-05-22 17:27:56 UTC
My patch should also make sure that whenever we flush the queues, any pending serialized queries should be woken up. See bug #700342 , which is probably related to this here.
Comment 25 Jens Georg 2013-05-24 06:53:08 UTC
No, nothing new. only that's not possible anymore to make it crash with any meaningful loglevel with your patch.
Comment 26 Sebastian Dröge (slomo) 2013-05-27 11:04:47 UTC
Should be good with latest git master, otherwise please reopen with

commit b6fac17502957bb4e10e73926da87f289a1d94b1
Author: Sebastian Dröge <slomo@circular-chaos.org>
Date:   Mon May 27 13:01:43 2013 +0200

    queue/queue2/multiqueue: When flushing, make sure to not lose any sticky events
    
    https://bugzilla.gnome.org/show_bug.cgi?id=688824