[Bug 783516] New: rtsp: Racy timeout when connecting to the server running change_state_intensive validate scenario
GStreamer (GNOME Bugzilla)
bugzilla at gnome.org
Wed Jun 7 15:06:24 UTC 2017
https://bugzilla.gnome.org/show_bug.cgi?id=783516
Bug ID: 783516
Summary: rtsp: Racy timeout when connecting to the server
running change_state_intensive validate scenario
Classification: Platform
Product: GStreamer
Version: 1.x
OS: Linux
Status: NEW
Severity: normal
Priority: Normal
Component: gst-plugins-good
Assignee: gstreamer-bugs at lists.freedesktop.org
Reporter: tsaunier at gnome.org
QA Contact: gstreamer-bugs at lists.freedesktop.org
GNOME version: ---
When running the GstValidate change_state_intensive scenario on RTSP stream, we
have a race where going back to PLAYING times out trying to connect to the
server to retrieve the SDP.
This issue happens with any stream.
Logs example:
=================
Test name: validate.rtsp.playback.change_state_intensive.vorbis_vp8_1_webm
Command:
'/home/thiblahute/devel/gstreamer/gst-build/build/subprojects/gst-devtools/validate/tools/gst-validate-1.0
playbin uri=rtsp://127.0.0.1:45897/test audio-sink=fakesink sync=true
video-sink=fakesink sync=true qos=true max-lateness=20000000 --set-media-info
/home/thiblahute/gst-validate/gst-integration-testsuites/medias/defaults/webm/vorbis_vp8.1.webm.media_info'
=================
=========================================
Running scenario change_state_intensive on pipeline playbin0
=========================================
Starting pipeline
Prerolling...
Pipeline started
Executing (40/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.396170150)
Executing (39/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.386018905)
Executing (38/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.370561907)
Executing (37/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.379416772)
Executing (36/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.372735544)
Executing (35/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.375469067)
Executing (34/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.372242035)
Executing (33/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.379282019)
Executing (32/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.384176014)
Executing (31/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.376992469)
Executing (30/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.380841170)
Executing (29/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.370176525)
Executing (28/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.375556683)
Executing (27/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.372499633)
Executing (26/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.384619616)
Executing (25/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.376216970)
Executing (24/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.377693217)
Executing (23/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.376284539)
Executing (22/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.374066716)
Executing (21/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.377430032)
Executing (20/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.382110615)
Executing (19/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.370325036)
Executing (18/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.379305769)
Executing (17/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.377927701)
Executing (16/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.380539763)
Executing (15/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.379554751)
Executing (14/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.374322413)
Executing (13/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
-> Action set-state done (duration: 0:00:00.376795187)
Executing (12/40) set-state: state=null repeat=40
Executing (subaction) set-state: state=playing
0:00:30.821920623 [332m14101[00m 0x561af013d230 [31;01mERROR [00m [00m
validate gst-validate-reporter.c:195:gst_validate_report_valist:[00m
<playbin0> 2258 (critical) : runtime: We got an ERROR message on the bus : Got
error: Could not read from resource. -- Debug message:
../subprojects/gst-plugins-good/gst/rtsp/gstrtspsrc.c(5449):
gst_rtspsrc_try_send ():
/GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin29/GstRTSPSrc:source:
Could not receive message. (Timeout while waiting for server response)
0:00:30.822518919 [332m14101[00m 0x561af00cda40 [31;01mERROR [00m [00;33m
gstvalidatescenario gst-validate-scenario.c:2700:message_cb:[00m Actions:
set-state, state=(string)null,
sub-action=(string)"set-state\,\ state\=playing", repeat=(int)40;
0:00:30.842309778 [332m14101[00m 0x561af00cda40 [31;01mERROR [00m [00m
validate gst-validate-reporter.c:195:gst_validate_report_valist:[00m
<change_state_intensive> 2261 (critical) : scenario: The program stopped before
some actions were executed : 1 actions were not executed:
set-state, state=(string)null,
sub-action=(string)"set-state\,\ state\=playing", repeat=(int)40;
Executing stop:
warning : received the same caps twice
Detected on <rtpvp8depay0:sink>
Detected on <vp8dec0:sink>
Detected on <vorbisdec0:sink>
Detected on <rtpvorbisdepay0:sink>
Detected on <rtpvp8depay1:sink>
Detected on <vp8dec1:sink>
Detected on <vorbisdec1:sink>
Detected on <rtpvorbisdepay1:sink>
Detected on <rtpvp8depay2:sink>
Detected on <vp8dec2:sink>
Detected on <vorbisdec2:sink>
Detected on <rtpvorbisdepay2:sink>
Detected on <rtpvp8depay3:sink>
Detected on <vp8dec3:sink>
Detected on <vorbisdec3:sink>
Detected on <rtpvorbisdepay3:sink>
Detected on <rtpvp8depay4:sink>
Detected on <vp8dec4:sink>
Detected on <vorbisdec4:sink>
Detected on <rtpvorbisdepay4:sink>
Detected on <rtpvp8depay5:sink>
Detected on <vp8dec5:sink>
Detected on <vorbisdec5:sink>
Detected on <rtpvorbisdepay5:sink>
Detected on <rtpvp8depay6:sink>
Detected on <vp8dec6:sink>
Detected on <vorbisdec6:sink>
Detected on <rtpvorbisdepay6:sink>
Detected on <rtpvp8depay7:sink>
Detected on <vp8dec7:sink>
Detected on <vorbisdec7:sink>
Detected on <rtpvorbisdepay7:sink>
Detected on <rtpvp8depay8:sink>
Detected on <vp8dec8:sink>
Detected on <vorbisdec8:sink>
Detected on <rtpvorbisdepay8:sink>
Detected on <rtpvp8depay9:sink>
Detected on <vp8dec9:sink>
Detected on <vorbisdec9:sink>
Detected on <rtpvorbisdepay9:sink>
Detected on <rtpvp8depay10:sink>
Detected on <vp8dec10:sink>
Detected on <vorbisdec10:sink>
Detected on <rtpvorbisdepay10:sink>
Detected on <rtpvp8depay11:sink>
Detected on <vp8dec11:sink>
Detected on <vorbisdec11:sink>
Detected on <rtpvorbisdepay11:sink>
Detected on <rtpvp8depay12:sink>
Detected on <vp8dec12:sink>
Detected on <vorbisdec12:sink>
Detected on <rtpvorbisdepay12:sink>
Detected on <rtpvp8depay13:sink>
Detected on <vp8dec13:sink>
Detected on <vorbisdec13:sink>
Detected on <rtpvorbisdepay13:sink>
Detected on <rtpvp8depay14:sink>
Detected on <vp8dec14:sink>
Detected on <vorbisdec14:sink>
Detected on <rtpvorbisdepay14:sink>
Detected on <rtpvp8depay15:sink>
Detected on <vp8dec15:sink>
Detected on <vorbisdec15:sink>
Detected on <rtpvorbisdepay15:sink>
Detected on <rtpvp8depay16:sink>
Detected on <vp8dec16:sink>
Detected on <vorbisdec16:sink>
Detected on <rtpvorbisdepay16:sink>
Detected on <rtpvp8depay17:sink>
Detected on <vp8dec17:sink>
Detected on <vorbisdec17:sink>
Detected on <rtpvorbisdepay17:sink>
Detected on <rtpvp8depay18:sink>
Detected on <vp8dec18:sink>
Detected on <vorbisdec18:sink>
Detected on <rtpvorbisdepay18:sink>
Detected on <rtpvp8depay19:sink>
Detected on <vp8dec19:sink>
Detected on <vorbisdec19:sink>
Detected on <rtpvorbisdepay19:sink>
Detected on <rtpvp8depay20:sink>
Detected on <vp8dec20:sink>
Detected on <vorbisdec20:sink>
Detected on <rtpvorbisdepay20:sink>
Detected on <rtpvp8depay21:sink>
Detected on <vp8dec21:sink>
Detected on <vorbisdec21:sink>
Detected on <rtpvorbisdepay21:sink>
Detected on <rtpvp8depay22:sink>
Detected on <vp8dec22:sink>
Detected on <vorbisdec22:sink>
Detected on <rtpvorbisdepay22:sink>
Detected on <rtpvp8depay23:sink>
Detected on <vp8dec23:sink>
Detected on <vorbisdec23:sink>
Detected on <rtpvorbisdepay23:sink>
Detected on <rtpvp8depay24:sink>
Detected on <vp8dec24:sink>
Detected on <vorbisdec24:sink>
Detected on <rtpvorbisdepay24:sink>
Detected on <rtpvp8depay25:sink>
Detected on <vp8dec25:sink>
Detected on <vorbisdec25:sink>
Detected on <rtpvorbisdepay25:sink>
Detected on <rtpvp8depay26:sink>
Detected on <vp8dec26:sink>
Detected on <vorbisdec26:sink>
Detected on <rtpvorbisdepay26:sink>
Detected on <rtpvp8depay27:sink>
Detected on <vp8dec27:sink>
Detected on <vorbisdec27:sink>
Detected on <rtpvorbisdepay27:sink>
warning : a new segment event has different value than the received one
Detected on <rtpvp8depay0:src>
Detected on <rtpvorbisdepay0:src>
Detected on <rtpvp8depay1:src>
Detected on <rtpvorbisdepay1:src>
Detected on <rtpvp8depay2:src>
Detected on <rtpvorbisdepay2:src>
Detected on <rtpvp8depay3:src>
Detected on <rtpvorbisdepay3:src>
Detected on <rtpvp8depay4:src>
Detected on <rtpvorbisdepay4:src>
Detected on <rtpvp8depay5:src>
Detected on <rtpvorbisdepay5:src>
Detected on <rtpvp8depay6:src>
Detected on <rtpvorbisdepay6:src>
Detected on <rtpvp8depay7:src>
Detected on <rtpvorbisdepay7:src>
Detected on <rtpvp8depay8:src>
Detected on <rtpvorbisdepay8:src>
Detected on <rtpvp8depay9:src>
Detected on <rtpvorbisdepay9:src>
Detected on <rtpvp8depay10:src>
Detected on <rtpvorbisdepay10:src>
Detected on <rtpvp8depay11:src>
Detected on <rtpvorbisdepay11:src>
Detected on <rtpvp8depay12:src>
Detected on <rtpvorbisdepay12:src>
Detected on <rtpvp8depay13:src>
Detected on <rtpvorbisdepay13:src>
Detected on <rtpvp8depay14:src>
Detected on <rtpvorbisdepay14:src>
Detected on <rtpvp8depay15:src>
Detected on <rtpvorbisdepay15:src>
Detected on <rtpvp8depay16:src>
Detected on <rtpvorbisdepay16:src>
Detected on <rtpvp8depay17:src>
Detected on <rtpvorbisdepay17:src>
Detected on <rtpvp8depay18:src>
Detected on <rtpvorbisdepay18:src>
Detected on <rtpvp8depay19:src>
Detected on <rtpvorbisdepay19:src>
Detected on <rtpvp8depay20:src>
Detected on <rtpvorbisdepay20:src>
Detected on <rtpvp8depay21:src>
Detected on <rtpvorbisdepay21:src>
Detected on <rtpvp8depay22:src>
Detected on <rtpvorbisdepay22:src>
Detected on <rtpvp8depay23:src>
Detected on <rtpvorbisdepay23:src>
Detected on <rtpvp8depay24:src>
Detected on <rtpvorbisdepay24:src>
Detected on <rtpvp8depay25:src>
Detected on <rtpvorbisdepay25:src>
Detected on <rtpvp8depay26:src>
Detected on <rtpvorbisdepay26:src>
Detected on <rtpvp8depay27:src>
Detected on <rtpvorbisdepay27:src>
Description : when receiving a new segment, an element should push
an equivalentsegment downstream
critical : We got an ERROR message on the bus
Detected on <playbin0>
Details : Got error: Could not read from resource. -- Debug
message: ../subprojects/gst-plugins-good/gst/rtsp/gstrtspsrc.c(5449):
gst_rtspsrc_try_send ():
/GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin29/GstRTSPSrc:source:
Could not receive message. (Timeout while waiting for
server response)
dotfile :
/home/thiblahute/.cache/gstmkdump//0:00:30.802809687-validate-report-critical-on-playbin0-runtime::error-on-bus.dot
backtrace :
gst_debug_get_stack_trace (gstinfo.c:2787)
gst_validate_report_new (gst-validate-report.c:710)
gst_validate_report_valist (gst-validate-reporter.c:186)
gst_validate_report (gst-validate-reporter.c:301)
_bus_handler (gst-validate-pipeline-monitor.c:503)
ffi_call_unix64 (/usr/lib/libffi.so.6.0.4:0x7fa294a0a1c4)
ffi_call (/usr/lib/libffi.so.6.0.4:0x7fa294a09c26)
g_cclosure_marshal_generic
(/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967cd7aa)
g_closure_invoke
(/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967ccecb)
?? (/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967def7e)
g_signal_emit_valist
(/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967e7bd8)
g_signal_emit
(/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967e7fbb)
gst_bus_sync_signal_handler (gstbus.c:1274)
gst_bus_post (gstbus.c:342)
gst_element_post_message_default (gstelement.c:1789)
gst_bin_post_message (gstbin.c:2856)
gst_element_post_message (gstelement.c:1832)
gst_bin_handle_message_func (gstbin.c:4107)
gst_pipeline_handle_message (gstpipeline.c:600)
gst_play_bin_handle_message (gstplaybin2.c:3012)
bin_bus_handler (gstbin.c:3327)
gst_bus_post (gstbus.c:336)
gst_element_post_message_default (gstelement.c:1789)
gst_bin_post_message (gstbin.c:2856)
gst_element_post_message (gstelement.c:1832)
gst_bin_handle_message_func (gstbin.c:4107)
handle_message (gsturidecodebin.c:2438)
bin_bus_handler (gstbin.c:3327)
gst_bus_post (gstbus.c:336)
gst_element_post_message_default (gstelement.c:1789)
gst_bin_post_message (gstbin.c:2856)
gst_element_post_message (gstelement.c:1832)
gst_element_message_full_with_details (gstelement.c:1968)
gst_element_message_full (gstelement.c:2007)
gst_rtspsrc_try_send (gstrtspsrc.c:5448)
gst_rtspsrc_send (gstrtspsrc.c:5520)
gst_rtspsrc_retrieve_sdp (gstrtspsrc.c:6684)
gst_rtspsrc_open (gstrtspsrc.c:6823)
gst_rtspsrc_thread (gstrtspsrc.c:7616)
gst_task_func (gsttask.c:332)
default_func (gsttaskpool.c:69)
?? (/usr/lib/libglib-2.0.so.0.5200.2:0x7fa296a81c8a)
?? (/usr/lib/libglib-2.0.so.0.5200.2:0x7fa296a81291)
start_thread (/usr/lib/libpthread-2.25.so:0x7fa296211293)
__clone (/usr/lib/libc-2.25.so:0x7fa295f5225b)
critical : The program stopped before some actions were executed
Detected on <change_state_intensive>
Details : 1 actions were not executed:
set-state, state=(string)null,
sub-action=(string)"set-state\,\ state\=playing", repeat=(int)40;
dotfile :
/home/thiblahute/.cache/gstmkdump//0:00:30.823199351-validate-report-critical-on-change_state_intensive-scenario::not-ended.dot
backtrace :
gst_debug_get_stack_trace (gstinfo.c:2787)
gst_validate_report_new (gst-validate-report.c:710)
gst_validate_report_valist (gst-validate-reporter.c:186)
gst_validate_report (gst-validate-reporter.c:301)
message_cb (gst-validate-scenario.c:2702)
ffi_call_unix64 (/usr/lib/libffi.so.6.0.4:0x7fa294a0a1c4)
ffi_call (/usr/lib/libffi.so.6.0.4:0x7fa294a09c26)
g_cclosure_marshal_generic
(/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967cd7aa)
g_closure_invoke
(/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967ccf71)
?? (/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967def7e)
g_signal_emit_valist
(/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967e7bd8)
g_signal_emit
(/usr/lib/libgobject-2.0.so.0.5200.2:0x7fa2967e7fbb)
gst_bus_async_signal_func (gstbus.c:1247)
gst_bus_source_dispatch (gstbus.c:841)
g_main_context_dispatch
(/usr/lib/libglib-2.0.so.0.5200.2:0x7fa296a59666)
?? (/usr/lib/libglib-2.0.so.0.5200.2:0x7fa296a59a1c)
g_main_loop_run
(/usr/lib/libglib-2.0.so.0.5200.2:0x7fa296a59d3e)
main (gst-validate.c:509)
__libc_start_main (/usr/lib/libc-2.25.so:0x7fa295e85436)
_start
(/home/thiblahute/devel/gstreamer/gst-build/build/subprojects/gst-devtools/validate/tools/gst-validate-1.0:0x561aee96f716)
==== Got criticals. Return value set to 18 ====
Critical error Got error: Could not read from resource. -- Debug message:
../subprojects/gst-plugins-good/gst/rtsp/gstrtspsrc.c(5449):
gst_rtspsrc_try_send ():
/GstPlayBin:playbin0/GstURIDecodeBin:uridecodebin29/GstRTSPSrc:source:
Could not receive message. (Timeout while waiting for server response)
Critical error 1 actions were not executed:
set-state, state=(string)null,
sub-action=(string)"set-state\,\ state\=playing", repeat=(int)40;
Issues found: 4
Returning 18 as errors were found
=======> Test FAILED (Return value: 18)
--
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