[Bug 757624] New: TEARDOWN request fails to execute properly and leave the RTSP-SERVER unresponsive to further client connections

GStreamer (GNOME Bugzilla) bugzilla at gnome.org
Thu Nov 5 01:29:28 PST 2015 

https://bugzilla.gnome.org/show_bug.cgi?id=757624

            Bug ID: 757624
           Summary: TEARDOWN request fails to execute properly and leave
                    the RTSP-SERVER unresponsive to further client
                    connections
    Classification: Platform
           Product: GStreamer
           Version: 1.6.1
                OS: Linux
            Status: NEW
          Severity: major
          Priority: Normal
         Component: gst-rtsp-server
          Assignee: gstreamer-bugs at lists.freedesktop.org
          Reporter: smalfoy at telsys.ch
        QA Contact: gstreamer-bugs at lists.freedesktop.org
     GNOME version: ---

Created attachment 314874
  --> https://bugzilla.gnome.org/attachment.cgi?id=314874&action=edit
Source code to generate the problem.

First, some context: 
I use Gstreamer 1.6.1 on a CentOS 7 server. I compiled it from the sources. The
modules I use are orc, gstreamer, gst-plugins-base, gst-plugins-good,
gst-rtsp-server, gst-libav, gst-plugins-bad and gst-plugins-ugly. I am building
a RTSP server delivering multicast video streams.

The problem I have can be generated with test examples delivered with the
gst-rtsp-server/examples. I slightly modified test-multicast.c, the source is
linked in attachement.

Symptoms:
Once the rtsp server is running, I use VLC from another machine to open the
video stream. It works fine.
After 5 to 10s I stop the stream (not pause) for a few seconds and reopen it.
If I repeat this cycle a few times the rtsp-server finally hangs and become
unresponsive to clients. I have seen that after just a few cycles (2 ou 3) and
sometimes up to 15 cycles. But it always ends up unresponsive.

So I activated the debug trace (./test-multicast --gst-debug=4) and did some
digging.

The trace when the TEARDOWN fails is in the file named FailedTeardown.txt. The
teardown start at time index 0:00:26.632497313 and hangs at time index
0:00:26.633378362. There are no error messages, no warnings, just
unresponsiveness. The timeout 30s later does not change anything.

--BEGIN TRACE--
0:00:24.012781235 31242 0x7f8c3c026de0 INFO              rtspstream
rtsp-stream.c:1530:dump_structure: structure: application/x-rtp-source-stats,
ssrc=(uint)1258972559, internal=(boolean)false, validated=(boolean)false,
received-bye=(boolean)false, is-csrc=(boolean)false, is-sender=(boolean)false,
seqnum-base=(int)-1, clock-rate=(int)-1,
rtcp-from=(string)192.168.192.180:5121, octets-sent=(guint64)0,
packets-sent=(guint64)0, octets-received=(guint64)0,
packets-received=(guint64)0, bitrate=(guint64)0, packets-lost=(int)0,
jitter=(uint)0, sent-pli-count=(uint)0, recv-pli-count=(uint)0,
sent-fir-count=(uint)0, recv-fir-count=(uint)0, have-sr=(boolean)false,
sr-ntptime=(guint64)0, sr-rtptime=(uint)0, sr-octet-count=(uint)0,
sr-packet-count=(uint)0, sent-rb=(boolean)false, sent-rb-fractionlost=(uint)0,
sent-rb-packetslost=(int)0, sent-rb-exthighestseq=(uint)0,
sent-rb-jitter=(uint)0, sent-rb-lsr=(uint)0, sent-rb-dlsr=(uint)0,
have-rb=(boolean)true, rb-fractionlost=(uint)254, rb-packetslost=(int)-1,
rb-exthighestseq=(uint)82553, rb-jitter=(uint)2, rb-lsr=(uint)0,
rb-dlsr=(uint)0, rb-round-trip=(uint)0;
0:00:24.012806958 31242 0x7f8c3c026de0 INFO              rtspstream
rtsp-stream.c:1556:find_transport: finding 192.168.192.180:5121 in 1 transports
0:00:24.012886467 31242 0x7f8c3c026de0 INFO              rtspstream
rtsp-stream.c:1627:on_ssrc_sdes: 0x7f8c3c00d640: new SDES 0x7f8bf7c44760
0:00:24.047644993 31242 0x7f8c2c002370 INFO               GST_EVENT
gstevent.c:679:gst_event_new_caps: creating caps event application/x-rtcp
0:00:24.047779825 31242 0x7f8c2c002370 INFO               GST_EVENT
gstevent.c:760:gst_event_new_segment: creating segment event time segment
start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999,
rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000,
base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:26.632497313 19649 0x7fe278002800 INFO              rtspclient
rtsp-client.c:2727:handle_request: client 0x197cab0: received a request
TEARDOWN rtsp://192.168.192.190:8554/test/ 1.0
0:00:26.632571859 19649 0x7fe278002800 INFO               rtspmedia
rtsp-media.c:3993:gst_rtsp_media_set_state: going to state NULL media
0x7fe298004340, target state PLAYING
0:00:26.632573104 19649 0x7fe2b0026de0 INFO              rtspstream
rtsp-stream.c:1530:dump_structure: structure: application/x-rtp-source-stats,
ssrc=(uint)1218512482, internal=(boolean)false, validated=(boolean)true,
received-bye=(boolean)false, is-csrc=(boolean)false, is-sender=(boolean)false,
seqnum-base=(int)-1, clock-rate=(int)-1,
rtcp-from=(string)192.168.192.180:5121, octets-sent=(guint64)0,
packets-sent=(guint64)0, octets-received=(guint64)0,
packets-received=(guint64)0, bitrate=(guint64)0, packets-lost=(int)0,
jitter=(uint)0, sent-pli-count=(uint)0, recv-pli-count=(uint)0,
sent-fir-count=(uint)0, recv-fir-count=(uint)0, have-sr=(boolean)false,
sr-ntptime=(guint64)0, sr-rtptime=(uint)0, sr-octet-count=(uint)0,
sr-packet-count=(uint)0, sent-rb=(boolean)false, sent-rb-fractionlost=(uint)0,
sent-rb-packetslost=(int)0, sent-rb-exthighestseq=(uint)0,
sent-rb-jitter=(uint)0, sent-rb-lsr=(uint)0, sent-rb-dlsr=(uint)0,
have-rb=(boolean)true, rb-fractionlost=(uint)0, rb-packetslost=(int)-1,
rb-exthighestseq=(uint)79883, rb-jitter=(uint)7, rb-lsr=(uint)1988069620,
rb-dlsr=(uint)270315, rb-round-trip=(uint)49;
0:00:26.632619408 19649 0x7fe278002800 INFO        GST_ELEMENT_PADS
gstpad.c:1991:gst_pad_unlink: unlinking udpsrc16:src(0x7fe2b000d6b0) and
funnel4:funnelpad16(0x7fe2b80202b0)
0:00:26.632819752 19649 0x7fe278002800 INFO        GST_ELEMENT_PADS
gstpad.c:2045:gst_pad_unlink: unlinked udpsrc16:src and funnel4:funnelpad16
0:00:26.632834880 19649 0x7fe278002800 INFO           GST_PARENTAGE
gstbin.c:1559:gst_bin_remove_func:<media-pipeline> removed child "udpsrc16"
0:00:26.632920951 19649 0x7fe2b0026d40 INFO                 basesrc
gstbasesrc.c:2734:gst_base_src_loop:<udpsrc16> pausing after
gst_base_src_get_range() = flushing
0:00:26.632979044 19649 0x7fe2b0026d40 INFO                    task
gsttask.c:315:gst_task_func:<udpsrc16:src> Task going to paused
0:00:26.632980466 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2305:gst_element_continue_state:<udpsrc16> committing state from
PLAYING to PAUSED, pending NULL, next READY
0:00:26.633025488 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc16> notifying about
state-changed PLAYING to PAUSED (NULL pending)
0:00:26.633042771 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2312:gst_element_continue_state:<udpsrc16> continue state change
PAUSED to READY, final NULL
0:00:26.633090572 19649 0x7fe2b0026d40 INFO                    task
gsttask.c:317:gst_task_func:<udpsrc16:src> Task resume from paused
0:00:26.633157407 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2305:gst_element_continue_state:<udpsrc16> committing state from
PAUSED to READY, pending NULL, next NULL
0:00:26.633172097 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc16> notifying about
state-changed PAUSED to READY (NULL pending)
0:00:26.633182543 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2312:gst_element_continue_state:<udpsrc16> continue state change
READY to NULL, final NULL
0:00:26.633226525 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2330:gst_element_continue_state:<udpsrc16> completed state change
to NULL
0:00:26.633242285 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc16> notifying about
state-changed READY to NULL (VOID_PENDING pending)
0:00:26.633254356 19649 0x7fe278002800 INFO         GST_REFCOUNTING
gstelement.c:2880:gst_element_dispose:<udpsrc16> dispose
0:00:26.633261641 19649 0x7fe278002800 INFO        GST_ELEMENT_PADS
gstelement.c:766:gst_element_remove_pad:<udpsrc16> removing pad 'src'
0:00:26.633275832 19649 0x7fe278002800 INFO         GST_REFCOUNTING
gstelement.c:2924:gst_element_dispose:<udpsrc16> parent class dispose
0:00:26.633284627 19649 0x7fe278002800 INFO         GST_REFCOUNTING
gstelement.c:2955:gst_element_finalize:<udpsrc16> finalize
0:00:26.633290794 19649 0x7fe278002800 INFO         GST_REFCOUNTING
gstelement.c:2960:gst_element_finalize:<udpsrc16> finalize parent
0:00:26.633300776 19649 0x7fe278002800 INFO        GST_ELEMENT_PADS
gstelement.c:766:gst_element_remove_pad:<funnel4> removing pad 'funnelpad16'
0:00:26.633319267 19649 0x7fe278002800 INFO        GST_ELEMENT_PADS
gstpad.c:1991:gst_pad_unlink: unlinking udpsrc17:src(0x7fe2b000cff0) and
funnel5:funnelpad17(0x7fe2b00284f0)
0:00:26.633334824 19649 0x7fe278002800 INFO        GST_ELEMENT_PADS
gstpad.c:2045:gst_pad_unlink: unlinked udpsrc17:src and funnel5:funnelpad17
0:00:26.633346407 19649 0x7fe278002800 INFO           GST_PARENTAGE
gstbin.c:1559:gst_bin_remove_func:<media-pipeline> removed child "udpsrc17"
0:00:26.633359954 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2305:gst_element_continue_state:<udpsrc17> committing state from
PLAYING to PAUSED, pending NULL, next READY
0:00:26.633368653 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc17> notifying about
state-changed PLAYING to PAUSED (NULL pending)
0:00:26.633378362 19649 0x7fe278002800 INFO              GST_STATES
gstelement.c:2312:gst_element_continue_state:<udpsrc17> continue state change
PAUSED to READY, final NULL
0:00:53.469097327 19649 0x7fe298002370 INFO              rtspstream
rtsp-stream.c:1677:on_timeout: 0x7fe2b000d640: source 0x7fe26bc44760 timeout
--END TRACE--



I collected the trace of the previous successfull TEARDOWN. It is in the file
SuccessfullTeardown.txt. The TEARDOWN starts at time index 0:00:17.063761305.

--BEGIN TRACE--
0:00:17.063761305 19649 0x7fe2b801c050 INFO              rtspclient
rtsp-client.c:2727:handle_request: client 0x197c9c0: received a request
TEARDOWN rtsp://192.168.192.190:8554/test/ 1.0
0:00:17.063788533 19649 0x7fe278002540 INFO              rtspstream
rtsp-stream.c:1530:dump_structure: structure: application/x-rtp-source-stats,
ssrc=(uint)2615844884, internal=(boolean)false, validated=(boolean)true,
received-bye=(boolean)false, is-csrc=(boolean)false, is-sender=(boolean)false,
seqnum-base=(int)-1, clock-rate=(int)-1,
rtcp-from=(string)192.168.192.180:5121, octets-sent=(guint64)0,
packets-sent=(guint64)0, octets-received=(guint64)0,
packets-received=(guint64)0, bitrate=(guint64)0, packets-lost=(int)0,
jitter=(uint)0, sent-pli-count=(uint)0, recv-pli-count=(uint)0,
sent-fir-count=(uint)0, recv-fir-count=(uint)0, have-sr=(boolean)false,
sr-ntptime=(guint64)0, sr-rtptime=(uint)0, sr-octet-count=(uint)0,
sr-packet-count=(uint)0, sent-rb=(boolean)false, sent-rb-fractionlost=(uint)0,
sent-rb-packetslost=(int)0, sent-rb-exthighestseq=(uint)0,
sent-rb-jitter=(uint)0, sent-rb-lsr=(uint)0, sent-rb-dlsr=(uint)0,
have-rb=(boolean)true, rb-fractionlost=(uint)0, rb-packetslost=(int)-1,
rb-exthighestseq=(uint)73821, rb-jitter=(uint)6, rb-lsr=(uint)1987555267,
rb-dlsr=(uint)157585, rb-round-trip=(uint)48;
0:00:17.063852744 19649 0x7fe2b801c050 INFO               rtspmedia
rtsp-media.c:3993:gst_rtsp_media_set_state: going to state NULL media
0x7fe27800a3f0, target state PLAYING
0:00:17.063862799 19649 0x7fe278002540 INFO              rtspstream
rtsp-stream.c:1556:find_transport: finding 192.168.192.180:5121 in 1 transports
0:00:17.063925605 19649 0x7fe278002540 INFO              rtspstream
rtsp-stream.c:1656:on_bye_ssrc: 0x7fe2b000cf80: source 0x7fe26bb4a760 bye
0:00:17.063929317 19649 0x7fe2b801c050 INFO        GST_ELEMENT_PADS
gstpad.c:1991:gst_pad_unlink: unlinking udpsrc10:src(0x7fe2b000d230) and
funnel2:funnelpad10(0x7fe2b000c270)
0:00:17.063954069 19649 0x7fe2b801c050 INFO        GST_ELEMENT_PADS
gstpad.c:2045:gst_pad_unlink: unlinked udpsrc10:src and funnel2:funnelpad10
0:00:17.063968212 19649 0x7fe2b801c050 INFO           GST_PARENTAGE
gstbin.c:1559:gst_bin_remove_func:<media-pipeline> removed child "udpsrc10"
0:00:17.064070159 19649 0x7fe278002800 INFO                 basesrc
gstbasesrc.c:2734:gst_base_src_loop:<udpsrc10> pausing after
gst_base_src_get_range() = flushing
0:00:17.064126198 19649 0x7fe278002800 INFO                    task
gsttask.c:315:gst_task_func:<udpsrc10:src> Task going to paused
0:00:17.064128089 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2305:gst_element_continue_state:<udpsrc10> committing state from
PLAYING to PAUSED, pending NULL, next READY
0:00:17.064172258 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc10> notifying about
state-changed PLAYING to PAUSED (NULL pending)
0:00:17.064211200 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2312:gst_element_continue_state:<udpsrc10> continue state change
PAUSED to READY, final NULL
0:00:17.064455938 19649 0x7fe278002800 INFO                    task
gsttask.c:317:gst_task_func:<udpsrc10:src> Task resume from paused
0:00:17.064535325 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2305:gst_element_continue_state:<udpsrc10> committing state from
PAUSED to READY, pending NULL, next NULL
0:00:17.064574067 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc10> notifying about
state-changed PAUSED to READY (NULL pending)
0:00:17.064600010 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2312:gst_element_continue_state:<udpsrc10> continue state change
READY to NULL, final NULL
0:00:17.064674429 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2330:gst_element_continue_state:<udpsrc10> completed state change
to NULL
0:00:17.064700396 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc10> notifying about
state-changed READY to NULL (VOID_PENDING pending)
0:00:17.064730834 19649 0x7fe2b801c050 INFO         GST_REFCOUNTING
gstelement.c:2880:gst_element_dispose:<udpsrc10> dispose
0:00:17.064753928 19649 0x7fe2b801c050 INFO        GST_ELEMENT_PADS
gstelement.c:766:gst_element_remove_pad:<udpsrc10> removing pad 'src'
0:00:17.064782694 19649 0x7fe2b801c050 INFO         GST_REFCOUNTING
gstelement.c:2924:gst_element_dispose:<udpsrc10> parent class dispose
0:00:17.064805848 19649 0x7fe2b801c050 INFO         GST_REFCOUNTING
gstelement.c:2955:gst_element_finalize:<udpsrc10> finalize
0:00:17.064826575 19649 0x7fe2b801c050 INFO         GST_REFCOUNTING
gstelement.c:2960:gst_element_finalize:<udpsrc10> finalize parent
0:00:17.064852595 19649 0x7fe2b801c050 INFO        GST_ELEMENT_PADS
gstelement.c:766:gst_element_remove_pad:<funnel2> removing pad 'funnelpad10'
0:00:17.064892955 19649 0x7fe2b801c050 INFO        GST_ELEMENT_PADS
gstpad.c:1991:gst_pad_unlink: unlinking udpsrc11:src(0x7fe2b80204f0) and
funnel3:funnelpad11(0x7fe2b8020070)
0:00:17.064929193 19649 0x7fe2b801c050 INFO        GST_ELEMENT_PADS
gstpad.c:2045:gst_pad_unlink: unlinked udpsrc11:src and funnel3:funnelpad11
0:00:17.064962412 19649 0x7fe2b801c050 INFO           GST_PARENTAGE
gstbin.c:1559:gst_bin_remove_func:<media-pipeline> removed child "udpsrc11"
0:00:17.065030332 19649 0x7fe278002540 INFO                 basesrc
gstbasesrc.c:2734:gst_base_src_loop:<udpsrc11> pausing after
gst_base_src_get_range() = flushing
0:00:17.065054573 19649 0x7fe278002540 INFO                    task
gsttask.c:315:gst_task_func:<udpsrc11:src> Task going to paused
0:00:17.065061012 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2305:gst_element_continue_state:<udpsrc11> committing state from
PLAYING to PAUSED, pending NULL, next READY
0:00:17.065089078 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc11> notifying about
state-changed PLAYING to PAUSED (NULL pending)
0:00:17.065113857 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2312:gst_element_continue_state:<udpsrc11> continue state change
PAUSED to READY, final NULL
0:00:17.065161598 19649 0x7fe278002540 INFO                    task
gsttask.c:317:gst_task_func:<udpsrc11:src> Task resume from paused
0:00:17.065200684 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2305:gst_element_continue_state:<udpsrc11> committing state from
PAUSED to READY, pending NULL, next NULL
0:00:17.065231286 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc11> notifying about
state-changed PAUSED to READY (NULL pending)
0:00:17.065267451 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2312:gst_element_continue_state:<udpsrc11> continue state change
READY to NULL, final NULL
0:00:17.065331785 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2330:gst_element_continue_state:<udpsrc11> completed state change
to NULL
0:00:17.065358449 19649 0x7fe2b801c050 INFO              GST_STATES
gstelement.c:2235:_priv_gst_element_state_changed:<udpsrc11> notifying about
state-changed READY to NULL (VOID_PENDING pending)
0:00:17.065383014 19649 0x7fe2b801c050 INFO         GST_REFCOUNTING
gstelement.c:2880:gst_element_dispose:<udpsrc11> dispose
0:00:17.065400257 19649 0x7fe2b801c050 INFO        GST_ELEMENT_PADS
gstelement.c:766:gst_element_remove_pad:<udpsrc11> removing pad 'src'
0:00:17.065425203 19649 0x7fe2b801c050 INFO         GST_REFCOUNTING
gstelement.c:2924:gst_element_dispose:<udpsrc11> parent class dispose
0:00:17.065450165 19649 0x7fe2b801c050 INFO         GST_REFCOUNTING
gstelement.c:2955:gst_element_finalize:<udpsrc11> finalize
0:00:17.065469591 19649 0x7fe2b801c050 INFO         GST_REFCOUNTING
gstelement.c:2960:gst_element_finalize:<udpsrc11> finalize parent
0:00:17.065492711 19649 0x7fe2b801c050 INFO        GST_ELEMENT_PADS
gstelement.c:766:gst_element_remove_pad:<funnel3> removing pad 'funnelpad11'
etc…
--END TRACE--


I compared the 2 traces to locates any difference. The only thing I noticed was
that some messages from the successfull TEARDOWN are absent from the failed
one. They are the following:

0:00:17.063925605 19649 0x7fe278002540 INFO              rtspstream
rtsp-stream.c:1656:on_bye_ssrc: 0x7fe2b000cf80: source 0x7fe26bb4a760 bye

0:00:17.065030332 19649 0x7fe278002540 INFO                 basesrc
gstbasesrc.c:2734:gst_base_src_loop:<udpsrc11> pausing after
gst_base_src_get_range() = flushing
0:00:17.065054573 19649 0x7fe278002540 INFO                    task
gsttask.c:315:gst_task_func:<udpsrc11:src> Task going to paused

0:00:17.065161598 19649 0x7fe278002540 INFO                    task
gsttask.c:317:gst_task_func:<udpsrc11:src> Task resume from paused


It looks like the TEARDOWN cannot continue because the media is not properly
stopped.

I have repeated this analysis 3 other times and each time I noticed the same
missing traces in the Failed TEARDOWN.

Am I correct in assuming this is a bug?
Is there any way around this problem while a fix is in the way?

Thanks.

-- 
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.

More information about the gstreamer-bugs mailing list