[gst-devel] Infinite loop on EOS
Daniel Drake
dsd at gentoo.org
Sat Dec 11 15:10:01 CET 2004
Hi,
I'm developing a program called tunesbrowser which downloads mp3 music over a
network (via DAAP/itunes protocol) and plays the stream through gstreamer.
I am experiencing gstreamer freezing at the end of each track. This happens
99% of the time. Running with --gst-debug-level=5 shows what appears to be an
infinite loop.
When the track is finishing, I get this in the logs:
DEBUG (0x8220a20 - 306336:35:03.663358000) GST_PADS( 5813)
gstpad.c(3292):gst_pad_pull: calling gst_probe_dispatcher_dispatch on data
0x81ba820
DEBUG (0x8220a20 - 306336:35:03.663375000) GST_DATAFLOW( 5813)
gstpad.c(3295):gst_pad_pull:<play_audio:sink> gst_pad_pull returned event
0x81ba820 (type 1, refcount 1)
LOG (0x8220a20 - 306336:35:03.663423000) alsa( 5813)
gstalsasink.c(378):gst_alsa_sink_loop:<play_audio> pulled data 0x81ba820 from
pad 0
LOG (0x8220a20 - 306336:35:03.663444000) alsa( 5813)
gstalsasink.c(383):gst_alsa_sink_loop:<play_audio> pulled data 0x81ba820 is an
event, checking
LOG (0x8220a20 - 306336:35:03.663462000) alsa( 5813)
gstalsasink.c(209):gst_alsa_sink_check_event:<play_audio> checking event
0x81ba820 of type 1 on sink pad 0
DEBUG (0x8220a20 - 306336:35:03.663515000) alsa( 5813)
gstalsa.c(1575):gst_alsa_drain_audio: stopping alsa
DEBUG (0x8220a20 - 306336:35:03.842047000) alsa( 5813)
gstalsa.c(1594):gst_alsa_drain_audio: stopped alsa
DEBUG (0x8220a20 - 306336:35:03.842131000) GST_EVENT( 5813)
gstelement.c(3469):gst_element_set_eos: setting EOS on element play_audio
DEBUG (0x8220a20 - 306336:35:03.842157000) default( 5813)
gstelement.c(2733):gst_element_set_state:<play_audio> setting state to PAUSED
LOG (0x8220a20 - 306336:35:03.842180000) GST_REFCOUNTING( 5813)
gstobject.c(226):gst_object_ref:<play_audio> ref 4->5
LOG (0x8220a20 - 306336:35:03.842202000) GST_REFCOUNTING( 5813)
gstobject.c(226):gst_object_ref:<play_audio> ref 5->6
INFO (0x8220a20 - 306336:35:03.842221000) GST_STATES( 5813)
gstelement.c(2768):gst_element_set_state_func:<play_audio> setting state from
PLAYING to PAUSED
DEBUG (0x8220a20 - 306336:35:03.842239000) GST_STATES( 5813)
gstelement.c(2791):gst_element_set_state_func:<play_audio> start: setting
current state PLAYING again
LOG (0x8220a20 - 306336:35:03.842286000) default( 5813)
gstclock.c(673):gst_clock_get_event_time_delay:<alsasinkclock> reporting new
event time 1102811703399554204
LOG (0x8220a20 - 306336:35:03.842310000) GST_REFCOUNTING( 5813)
gstobject.c(226):gst_object_ref:<play_audio> ref 6->7
LOG (0x8220a20 - 306336:35:03.842328000) GST_STATES( 5813)
gstelement.c(2965):gst_element_change_state:<play_audio> default handler tries
setting state from PLAYING to PA
USED (0804)
LOG (0x8220a20 - 306336:35:03.842348000) default( 5813)
gstclock.c(669):gst_clock_get_event_time_delay:<alsasinkclock> reporting last
event time 1102811703399554204
LOG (0x8220a20 - 306336:35:03.842367000) GST_CLOCK( 5813)
gstelement.c(2979):gst_element_change_state:<play_audio> setting base time to
31895510204
DEBUG (0x8220a20 - 306336:35:03.842397000) GST_PADS( 5813)
gstpad.c(466):gst_pad_set_active: de-activating pad play_audio:sink
LOG (0x8220a20 - 306336:35:03.842439000) GST_EVENT( 5813)
gstobject.c(369):gst_object_dispatch_properties_changed: deep notification
from sink to play_audio (active)
LOG (0x8220a20 - 306336:35:03.842461000) GST_EVENT( 5813)
gstobject.c(369):gst_object_dispatch_properties_changed: deep notification
from sink to pipeline (active)
LOG (0x8220a20 - 306336:35:03.842484000) GST_STATES( 5813)
gstelement.c(3028):gst_element_change_state:<play_audio> signaling state
change from PLAYING to PAUSED
DEBUG (0x8220a20 - 306336:35:03.842503000) scheduler( 5813)
gstoptimalscheduler.c(1553):gst_opt_scheduler_state_transition: element
"play_audio" state change (0804)
LOG (0x8220a20 - 306336:35:03.842571000) scheduler( 5813)
gstoptimalscheduler.c(1079):group_element_set_enabled: request to 0 element
play_audio in group 0x81f04a8, have
1 elements enabled out of 1
DEBUG (0x8220a20 - 306336:35:03.842591000) scheduler( 5813)
gstoptimalscheduler.c(1113):group_element_set_enabled: disable element
play_audio in group 0x81f04a8, now 0 ele
ments enabled out of 1
LOG (0x8220a20 - 306336:35:03.842607000) scheduler( 5813)
gstoptimalscheduler.c(1120):group_element_set_enabled: disable group 0x81f04a8
LOG (0x8220a20 - 306336:35:03.842623000) scheduler( 5813)
gstoptimalscheduler.c(728):chain_group_set_enabled: request to 0 group
0x81f04a8 in chain 0x8218998, have 1 gro
ups enabled out of 3
DEBUG (0x8220a20 - 306336:35:03.842640000) scheduler( 5813)
gstoptimalscheduler.c(762):chain_group_set_enabled: disable group 0x81f04a8 in
chain 0x8218998, now 0 groups en
abled out of 3
DEBUG (0x8220a20 - 306336:35:03.842656000) scheduler( 5813)
gstoptimalscheduler.c(765):chain_group_set_enabled: disable chain 0x8218998
LOG (0x8220a20 - 306336:35:03.842675000) GST_STATES( 5813)
gstbin.c(673):gst_bin_child_state_change: child play_audio changed state in
bin pipeline from PLAYING to PAUSED
LOG (0x8220a20 - 306336:35:03.842695000) GST_THREAD( 5813)
gstthread.c(594):gst_thread_child_state_change:<pipeline> (from thread
pipeline) child play_audio changed state
from PLAYING to PAUSED
LOG (0x8220a20 - 306336:35:03.842714000) bin( 5813)
gstbin.c(700):gst_bin_child_state_change_func:<pipeline> before child state
change: 3 elements: 1 PLAYING, 2 PA
USED, 0 READY, 0 NULL, own state: PLAYING
DEBUG (0x8220a20 - 306336:35:03.842733000) GST_STATES( 5813)
gstbin.c(711):gst_bin_child_state_change_func:<pipeline> highest child state
is PAUSED, changing bin state acco
rdingly
LOG (0x8220a20 - 306336:35:03.842751000) GST_STATES( 5813)
gstbin.c(901):gst_bin_change_state_norecurse:<pipeline> setting bin's own state
LOG (0x8220a20 - 306336:35:03.842770000) GST_REFCOUNTING( 5813)
gstobject.c(226):gst_object_ref:<pipeline> ref 3->4
LOG (0x8220a20 - 306336:35:03.842788000) GST_STATES( 5813)
gstelement.c(2965):gst_element_change_state:<pipeline> default handler tries
setting state from PLAYING to PAUS
ED (0804)
LOG (0x8220a20 - 306336:35:03.842807000) GST_STATES( 5813)
gstelement.c(3028):gst_element_change_state:<pipeline> signaling state change
from PLAYING to PAUSED
DEBUG (0x8220a20 - 306336:35:03.842822000) scheduler( 5813)
gstoptimalscheduler.c(1553):gst_opt_scheduler_state_transition: element
"pipeline" state change (0804)
LOG (0x8220a20 - 306336:35:03.842838000) scheduler( 5813)
gstoptimalscheduler.c(1559):gst_opt_scheduler_state_transition: parent
"pipeline" changed state
INFO (0x8220a20 - 306336:35:03.842853000) scheduler( 5813)
gstoptimalscheduler.c(1563):gst_opt_scheduler_state_transition: setting
scheduler state to stopped
LOG (0x8220a20 - 306336:35:03.842874000) GST_REFCOUNTING( 5813)
gstobject.c(246):gst_object_unref:<pipeline> unref 4->3
LOG (0x8220a20 - 306336:35:03.842891000) bin( 5813)
gstbin.c(719):gst_bin_child_state_change_func:<pipeline> after child state
change: 3 elements: 0 PLAYING, 3 PAU
SED, 0 READY, 0 NULL, own state: PAUSED
LOG (0x8220a20 - 306336:35:03.842936000) GST_THREAD( 5813)
gstthread.c(601):gst_thread_child_state_change:<play_audio> we are in the
thread context
LOG (0x8220a20 - 306336:35:03.842955000) GST_THREAD( 5813)
gstthread.c(624):gst_thread_child_state_change:<play_audio> done child state
change
LOG (0x8220a20 - 306336:35:03.842974000) GST_REFCOUNTING( 5813)
gstobject.c(246):gst_object_unref:<play_audio> unref 7->6
LOG (0x8220a20 - 306336:35:03.842993000) GST_REFCOUNTING( 5813)
gstobject.c(246):gst_object_unref:<play_audio> unref 6->5
LOG (0x8220a20 - 306336:35:03.843011000) GST_REFCOUNTING( 5813)
gstobject.c(246):gst_object_unref:<play_audio> unref 5->4
DEBUG (0x8220a20 - 306336:35:03.843028000) GST_EVENT( 5813)
gstelement.c(3446):gst_element_set_eos_recursive: setting recursive EOS on
play_audio
DEBUG (0x8220a20 - 306336:35:03.843046000) GST_EVENT( 5813)
gstelement.c(3446):gst_element_set_eos_recursive: setting recursive EOS on
pipeline
Next, my application uses gst_element_set_state to change state to READY
DEBUG (0x8091190 - 306336:35:03.843136000) default( 5813)
gstelement.c(2733):gst_element_set_state:<pipeline> setting state to READY
LOG (0x8091190 - 306336:35:03.843156000) GST_REFCOUNTING( 5813)
gstobject.c(226):gst_object_ref:<pipeline> ref 4->5
LOG (0x8091190 - 306336:35:03.843175000) GST_REFCOUNTING( 5813)
gstobject.c(226):gst_object_ref:<pipeline> ref 5->6
INFO (0x8091190 - 306336:35:03.843192000) GST_STATES( 5813)
gstelement.c(2768):gst_element_set_state_func:<pipeline> setting state from
PAUSED to READY
DEBUG (0x8091190 - 306336:35:03.843210000) GST_STATES( 5813)
gstelement.c(2791):gst_element_set_state_func:<pipeline> start: setting
current state PAUSED again
DEBUG (0x8091190 - 306336:35:03.843227000) GST_THREAD( 5813)
gstthread.c(443):gst_thread_change_state:<pipeline> changing state from PAUSED
to READY
LOG (0x8091190 - 306336:35:03.843244000) GST_THREAD( 5813)
gstthread.c(449):gst_thread_change_state:<pipeline> grabbing lock
DEBUG (0x8091190 - 306336:35:03.843262000) GST_THREAD( 5813)
gstthread.c(407):gst_thread_sync:<pipeline> syncing thread, grabbing lock
The infinite loop starts now:
LOG (0x8091190 - 306336:35:03.843278000) GST_THREAD( 5813)
gstthread.c(416):gst_thread_sync:<pipeline> syncing thread...
DEBUG (0x8091190 - 306336:35:03.843296000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"pipe_source"
DEBUG (0x8091190 - 306336:35:03.843323000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"decoder"
DEBUG (0x8091190 - 306336:35:03.843342000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"play_audio"
DEBUG (0x8091190 - 306336:35:03.843369000) GST_THREAD( 5813)
gstthread.c(422):gst_thread_sync:<pipeline> wait
LOG (0x8091190 - 306336:35:03.845473000) GST_THREAD( 5813)
gstthread.c(416):gst_thread_sync:<pipeline> syncing thread...
DEBUG (0x8091190 - 306336:35:03.845498000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"pipe_source"
DEBUG (0x8091190 - 306336:35:03.845544000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"decoder"
DEBUG (0x8091190 - 306336:35:03.845563000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"play_audio"
DEBUG (0x8091190 - 306336:35:03.845581000) GST_THREAD( 5813)
gstthread.c(422):gst_thread_sync:<pipeline> wait
LOG (0x8091190 - 306336:35:03.847402000) GST_THREAD( 5813)
gstthread.c(416):gst_thread_sync:<pipeline> syncing thread...
DEBUG (0x8091190 - 306336:35:03.847424000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"pipe_source"
DEBUG (0x8091190 - 306336:35:03.847441000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"decoder"
DEBUG (0x8091190 - 306336:35:03.847459000) GST_THREAD( 5813)
gstthread.c(348):gst_thread_release_children_locks:<pipeline> waking element
"play_audio"
DEBUG (0x8091190 - 306336:35:03.847477000) GST_THREAD( 5813)
gstthread.c(422):gst_thread_sync:<pipeline> wait
And this repeats over and over. The gst_element_set_state call (to set READY)
never returns.
Any pointers where to start debugging would be much appreciated. I don't have
a great deal of gstreamer knowledge, and unfortunately the software author
only very infrequently runs into this problem. I am running gstreamer 0.8.7
with gst-plugins 0.8.6 (also tried 0.8.5).
Thanks,
Daniel
More information about the gstreamer-devel
mailing list