GNOME Bugzilla – Bug 783516
rtsp: Racy timeout when connecting to the server running change_state_intensive validate scenario
Last modified: 2018-11-03 15:19:31 UTC
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)
-- GitLab Migration Automatic Message -- This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity. You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/gstreamer/gst-plugins-good/issues/377.