rtspsrc: rtcp interleaved over tcp+tls without prefix in v1.16.0
I'm using rtsp over tls, with interleaved transport, like so: rtspsrc name=mux location=rtsps://devbox:8556/test-pierce latency=0 protocols=tcp tls-validation-flags=0x58 do-rtcp=true
. (TLS validation disabled for my local debugging server, do-rtcp=true
is the default but I'm switching it periodically for debugging.) Interleaved transport sends rtp and rtcp over the same connection as the RTSP request/response, but each rtp/rtcp frame is prefixed with 4 bytes: "$", 1-byte channel, 2-bytes big-endian length.
In this specific setup, rtcp is sent without that 4-byte prefix, by gstreamer-1.16.0. (And then if I hack my server-side parser to accept that, something else fails on the client side about 100ms later.)
- This only happens for rtsps:// not for rtsp://
- This bug was not present in 1.14.x
- The source or trigger of the issue seems to be in gst-plugins-base, not gst-plugins-good: if I switch just gst-plugins-base between 1.16.0 and 1.14.4 I can see the issue come and go
- If I use
do-rtcp=false
all seems OK, the video stream continues playing for many minutes.
Here's some rather verbose logging from the rtspsrc:
0:00:01.762490000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5481:gst_rtspsrc_loop_interleaved:<mux> doing receive with timeout 8633 seconds, 521054 usec
0:00:01.762682000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5491:gst_rtspsrc_loop_interleaved:<mux> we received a server message
0:00:01.762693000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5524:gst_rtspsrc_loop_interleaved:<mux> got data message
0:00:01.762701000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5290:gst_rtspsrc_handle_data:<mux> pushing data of size 115 on channel 0
0:00:01.762725000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5481:gst_rtspsrc_loop_interleaved:<mux> doing receive with timeout 8633 seconds, 520819 usec
0:00:01.770797000 6577 0x7fdf2e857d90 DEBUG rtspsrc gstrtspsrc.c:3115:gst_rtspsrc_sink_chain:<mux> sending 84 bytes RTCP
0:00:01.770878000 6577 0x7fdf2e857d90 DEBUG rtspsrc gstrtspsrc.c:3117:gst_rtspsrc_sink_chain:<mux> sent RTCP, 0
0:00:01.781007000 6577 0x7fdf2e857ca0 DEBUG rtspsrc gstrtspsrc.c:2862:gst_rtspsrc_handle_src_event:<mux> pad mux:recv_rtp_src_0_2345423449_96 received event qos
0:00:01.781037000 6577 0x7fdf2e857ca0 DEBUG rtspsrc gstrtspsrc.c:2928:gst_rtspsrc_handle_internal_src_event:<'':internalsrc_0> received event qos
0:00:01.795760000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5491:gst_rtspsrc_loop_interleaved:<mux> we received a server message
0:00:01.795775000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5524:gst_rtspsrc_loop_interleaved:<mux> got data message
0:00:01.795785000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5290:gst_rtspsrc_handle_data:<mux> pushing data of size 84 on channel 1
0:00:01.795807000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5481:gst_rtspsrc_loop_interleaved:<mux> doing receive with timeout 8633 seconds, 487736 usec
0:00:01.795989000 6577 0x7fdf30807e80 WARN rtspsrc gstrtspsrc.c:5558:gst_rtspsrc_loop_interleaved:<mux> error: Could not receive message. (Parse error)
0:00:01.796028000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:6037:gst_rtspsrc_loop:<mux> pausing task, reason error
0:00:01.796036000 6577 0x7fdf30807e80 WARN rtspsrc gstrtspsrc.c:6054:gst_rtspsrc_loop:<mux> error: Internal data stream error.
0:00:01.796040000 6577 0x7fdf30807e80 WARN rtspsrc gstrtspsrc.c:6054:gst_rtspsrc_loop:<mux> error: streaming stopped, reason error (-5)
0:00:01.796111000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5939:gst_rtspsrc_loop_send_cmd:<mux> sending cmd WAIT
0:00:01.796116000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5964:gst_rtspsrc_loop_send_cmd:<mux> cancel previous request LOOP
0:00:01.796135000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5972:gst_rtspsrc_loop_send_cmd:<mux> connection flush busy LOOP
0:00:01.796139000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5090:gst_rtspsrc_connection_flush:<mux> set flushing 1
0:00:01.796143000 6577 0x7fdf30807e80 DEBUG rtspsrc gstrtspsrc.c:5093:gst_rtspsrc_connection_flush:<mux> connection flush
ERROR: from element /GstPipeline:pipeline0/GstRTSPSrc:mux: Could not read from resource.
Additional debug info:
gstrtspsrc.c(5558): gst_rtspsrc_loop_interleaved (): /GstPipeline:pipeline0/GstRTSPSrc:mux:
Could not receive message. (Parse error)
Execution ended after 0:00:01.546659000
Setting pipeline to PAUSED ...
and here's what my custom rtsp server debug logs (server hacked to detect interleaved rtcp without prefix):
2019-07-29 21:13:09.441 D (rtsp_serve.c:536) LINE: PLAY rtsp://devbox:8556/test-pierce RTSP/1.0
2019-07-29 21:13:09.441 D (rtsp_serve.c:543) HDR: CSeq: 3
2019-07-29 21:13:09.441 D (rtsp_serve.c:543) HDR: User-Agent: GStreamer/1.16.0
2019-07-29 21:13:09.441 D (rtsp_serve.c:543) HDR: Range: npt=0-
2019-07-29 21:13:09.442 D (rtsp_serve.c:543) HDR: Session: 7xImOMpUZ6BzGJQ
2019-07-29 21:13:09.442 D (rtsp_serve.c:543) HDR: Date: Mon, 29 Jul 2019 21:13:09 GMT
2019-07-29 21:13:09.442 I (rtsp_serve.c:500) rtsp < PLAY rtsp://devbox:8556/test-pierce - rtsps-peer=172.30.1.1:60956
2019-07-29 21:13:09.442 D (rtsp_engine.c:346) Client request uri acceptable
2019-07-29 21:13:09.443 V (rtsp_engine.c:389) Auth accepted rtsps-peer=172.30.1.1:60956 uri=rtsp://devbox:8556/test-pierce need_players=0
2019-07-29 21:13:09.443 D (rtsp_engine.c:730) RTSP Play rtsps-peer=172.30.1.1:60956 rtsp://devbox:8556/test-pierce
2019-07-29 21:13:09.443 D (rtsp_media.c:151) media pool[0] found presentation at (/test-pierce)
2019-07-29 21:13:09.443 I (rtsp_serve.c:638) rtsp > 200 OK - rtsps-peer=172.30.1.1:60956
2019-07-29 21:13:09.444 V (rtsp_serve.c:675) rtsp connection now playing rtsps-peer=172.30.1.1:60956
2019-07-29 21:13:09.444 D (rtsp_serve.c:690) rtsp >
RTSP/1.0 200 OK
Server: avcore/1.7
CSeq: 3
RTP-Info: /test-pierce
Session: 7xImOMpUZ6BzGJQ
2019-07-29 21:13:09.445 I (rtsp_engine.c:1064) attempt to prepare burst, max=0.750000
2019-07-29 21:13:09.445 D (rtsp_engine.c:1086) consider burst for H264 : 1
2019-07-29 21:13:09.446 I (rtsp_engine.c:1100) h264 burst candidate pts=107.834133 dur=0.419211 pkts=61
2019-07-29 21:13:09.446 I (rtsp_engine.c:1138) sending burst, 61 pkts
2019-07-29 21:13:09.446 V (rtsp_auth.c:514) Sending media:play_start API request (127.0.0.1:8501/int/media/state?urn=%2Ftest-pierce)
2019-07-29 21:13:09.447 D (rtsp_engine.c:1162) finished H264 burst
2019-07-29 21:13:09.451 E (rtsp_auth.c:555) Failure response for media state request 400 /int/media/state?urn=%2Ftest-pierce
2019-07-29 21:13:10.952 W (rtsp_serve.c:403) received rtcp interleaved without prefix rtsps-peer=172.30.1.1:60956
2019-07-29 21:13:10.952 D (rtp_pkt.c:156) v=2 p=0 cnt=1 pt=RR len=32 ssrc=31c3ca9c
2019-07-29 21:13:10.953 W (rtsp_serve.c:403) received rtcp interleaved without prefix rtsps-peer=172.30.1.1:60956
2019-07-29 21:13:10.953 D (rtp_pkt.c:171) v=2 p=0 cnt=1 pt=SDES len=52 ssrc=31c3ca9c type=1
2019-07-29 21:13:10.990 D (rtsp_serve.c:536) LINE: TEARDOWN rtsp://devbox:8556/test-pierce RTSP/1.0
2019-07-29 21:13:10.991 D (rtsp_serve.c:543) HDR: CSeq: 4
2019-07-29 21:13:10.991 D (rtsp_serve.c:543) HDR: User-Agent: GStreamer/1.16.0
2019-07-29 21:13:10.991 D (rtsp_serve.c:543) HDR: Session: 7xImOMpUZ6BzGJQ
2019-07-29 21:13:10.991 D (rtsp_serve.c:543) HDR: Date: Mon, 29 Jul 2019 21:13:11 GMT
2019-07-29 21:13:10.992 I (rtsp_serve.c:500) rtsp < TEARDOWN rtsp://devbox:8556/test-pierce - rtsps-peer=172.30.1.1:60956
note that the stream works and the video shows up for half a second, before the gstreamer client attempts to send an rtcp receiver-report and SDES, and then dies (regardless of whether the server tolerates the un-prefixed rtcp).