rtpbin RTCP connection first sends a RR (receiver report) than a SR (sender report) - random behavior

[Thomas Roos]

gstrtpbin 0.10.31
AND rtpbin 1.0.3


why is rtpbin (as a sender) first sending RTCP RR  (receiver report)
and than a SR (sender report) - AND this sometimes this behavior
changes.
I also can confirm this behavior in wireshark and with a c program
I think it's a threading error, so that rtpbin is sending RR if it has
no rtp encoded data yet.
-> is this an error?
-> how to fix? hack? workaround?

merry x-mas, cheers Thomas


sender pipeline:
gst-launch -v gstrtpbin name=rtpbin  !  audiotestsrc wave=8
is-live=true ! alawenc ! rtppcmapay !  rtpbin.send_rtp_sink_0
rtpbin.send_rtp_src_0 !  udpsink  host=224.1.1.1 auto-multicast=true
port=3000 rtpbin.send_rtcp_src_0 ! multiudpsink
clients="127.0.0.1:9997,192.168.106.173:10010" sync=false async=false
udpsrc port=10000 ! rtpbin.recv_rtcp_sink_0


receiver pipelines (don't care):
gst-launch -v gstrtpbin name=rtpbin ntp-sync=true udpsrc
caps="application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, payload=(int)8" multicast-group=224.1.1.1
auto-multicast=true port=3000   ! rtpbin.recv_rtp_sink_0 rtpbin. !
rtppcmadepay ! alawdec ! alsasink ts-offset=1000000
drift-tolerance=100 sync=true slave-method=2 udpsrc port=9997 !
rtpbin.recv_rtcp_sink_0\ rtpbin.send_rtcp_src_0 ! multiudpsink
clients="192.168.106.37:10000" sync=false async=false

gst-launch -v gstrtpbin name=rtpbin ntp-sync=true udpsrc
caps="application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, payload=(int)8" multicast-group=224.1.1.1
auto-multicast=true port=3000   ! rtpbin.recv_rtp_sink_0 rtpbin. !
rtppcmadepay ! alawdec ! alsasink ts-offset=1000000
drift-tolerance=100 sync=true slave-method=2 udpsrc port=10010 !
rtpbin.recv_rtcp_sink_0\ rtpbin.send_rtcp_src_0 ! multiudpsink
clients="192.168.106.37:10000" sync=false async=false


sender log:

first a RR (last line):
0:00:00.017692288 18492       0xd51d60 DEBUG             rtpsession
rtpsession.c:582:rtp_session_init: 0xd6a0d0: session using SSRC:
3d26ebed
0:00:00.017856400 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:2097:gst_rtp_session_request_new_pad:<rtpsession0>
requesting pad recv_rtcp_sink
0:00:00.017885398 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:1945:create_recv_rtcp_sink:<rtpsession0> creating RTCP
sink pad
0:00:00.017915912 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:1960:create_recv_rtcp_sink:<rtpsession0> creating sync
src pad
0:00:00.018118441 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:2097:gst_rtp_session_request_new_pad:<rtpsession0>
requesting pad send_rtp_sink
0:00:00.018131401 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:1996:create_send_rtp_sink:<rtpsession0> creating pad
0:00:00.018266703 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:1775:gst_rtp_session_getcaps_send_rtp:<rtpsession0>
getting caps application/x-rtp, ssrc=(uint)1025960941;
application/x-rtp
0:00:00.018321732 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:2097:gst_rtp_session_request_new_pad:<rtpsession0>
requesting pad send_rtcp_src
0:00:00.018338584 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:2052:create_send_rtcp_src:<rtpsession0> creating pad
Leitung wird auf PAUSIERT gesetzt ...
/GstPipeline:pipeline0/GstAudioTestSrc:audiotestsrc0.GstPad:src: caps
= audio/x-raw-int, channels=(int)1, rate=(int)8000, width=(int)16,
depth=(int)16, endianness=(int)1234, signed=(boolean)true
Leitung ist aktiv und erfordert keinen VORLAUF …
Leitung wird auf ABSPIELEN gesetzt ...
0:00:00.019114180 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:1625:gst_rtp_session_query_send_rtcp_src:<rtpsession0>
received QUERY
0:00:00.019131140 18492       0xd51d60 WARN                     bin
gstbin.c:2399:gst_bin_do_latency_func:<pipeline0> failed to query
latency
0:00:00.019166060 18492       0xd51d60 DEBUG             rtpsession
gstrtpsession.c:901:start_rtcp_thread:<rtpsession0> starting RTCP
thread
New clock: GstSystemClock
0:00:00.019268508 18492       0xd690f0 DEBUG             rtpsession
gstrtpsession.c:833:rtcp_thread:<rtpsession0> entering RTCP thread
0:00:00.019290731 18492       0xd690f0 DEBUG             rtpsession
gstrtpsession.c:843:rtcp_thread:<rtpsession0> starting at
6:18:03.230396815
0:00:00.019299354 18492       0xd690f0 DEBUG             rtpsession
rtpsession.c:2724:rtp_session_next_timeout: current time:
6:18:03.230396815, next time: 0:00:00.000000000
0:00:00.019306440 18492       0xd690f0 DEBUG             rtpsession
gstrtpsession.c:853:rtcp_thread:<rtpsession0> next check time
0:00:00.000000000
0:00:00.019311010 18492       0xd690a0 DEBUG             rtpsession
gstrtpsession.c:1682:gst_rtp_session_event_send_rtp_sink:<rtpsession0>
received event
0:00:00.019327002 18492       0xd690a0 DEBUG             rtpsession
gstrtpsession.c:1711:gst_rtp_session_event_send_rtp_sink:<rtpsession0>
configured NEWSEGMENT update 0, rate 1,000000, applied rate 1,000000,
format GST_FORMAT_TIME, 0:00:00.000000000 -- 99:99:99.999999999, time
0:00:00.000000000, accum 0:00:00.000000000
0:00:00.019317234 18492       0xd690f0 DEBUG             rtpsession
gstrtpsession.c:881:rtcp_thread:<rtpsession0> unlocked 1, current
6:18:03.230423153
0:00:00.019354234 18492       0xd690a0 DEBUG             rtpsession
gstrtpsession.c:1682:gst_rtp_session_event_send_rtp_sink:<rtpsession0>
received event
0:00:00.019399141 18492       0xd690f0 DEBUG             rtpsession
rtpsession.c:3118:rtp_session_on_timeout: reporting at
6:18:03.230423153, NTP time 990276:09:12.131919000
0:00:00.019443489 18492       0xd690f0 DEBUG             rtpsession
rtpsession.c:2573:calculate_rtcp_interval: next deterministic
interval: 0:00:02.500000000, first 1
0:00:00.019465074 18492       0xd690f0 DEBUG             rtpsession
rtpsession.c:2578:calculate_rtcp_interval: next interval:
0:00:02.500000000
0:00:00.019491276 18492       0xd690f0 LOG               rtpsession
rtpsession.c:2858:session_cleanup: timeout base interval
0:00:02.500000000
0:00:00.019512737 18492       0xd690f0 DEBUG             rtpsession
rtpsession.c:2573:calculate_rtcp_interval: next deterministic
interval: 0:00:05.000000000, first 0
/GstPipeline:pipeline0/GstALawEnc:alawenc0.GstPad:sink: caps =
audio/x-raw-int, rate=(int)8000, channels=(int)1,
endianness=(int)1234, width=(int)16, depth=(int)16,
signed=(boolean)true
0:00:00.019522933 18492       0xd690f0 DEBUG             rtpsession
rtpsession.c:2578:calculate_rtcp_interval: next interval:
0:00:03.939187470
0:00:00.019543149 18492       0xd690f0 DEBUG             rtpsession
rtpsession.c:3049:is_rtcp_time: can send RTCP now, next interval
0:00:03.939187470
/GstPipeline:pipeline0/GstALawEnc:alawenc0.GstPad:src: caps =
audio/x-alaw, rate=(int)8000, channels=(int)1
0:00:00.019558134 18492       0xd690f0 DEBUG             rtpsession
rtpsession.c:2774:session_start_rtcp: create RR for SSRC 3d26ebed



first a SR (last line) :
0:00:00.017141677 18520      0x1e41d60 DEBUG             rtpsession
rtpsession.c:582:rtp_session_init: 0x1e5a0d0: session using SSRC:
6b2b19f2
0:00:00.017295789 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:2097:gst_rtp_session_request_new_pad:<rtpsession0>
requesting pad recv_rtcp_sink
0:00:00.017309927 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:1945:create_recv_rtcp_sink:<rtpsession0> creating RTCP
sink pad
0:00:00.017346170 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:1960:create_recv_rtcp_sink:<rtpsession0> creating sync
src pad
0:00:00.017533979 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:2097:gst_rtp_session_request_new_pad:<rtpsession0>
requesting pad send_rtp_sink
0:00:00.017546924 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:1996:create_send_rtp_sink:<rtpsession0> creating pad
0:00:00.017677554 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:1775:gst_rtp_session_getcaps_send_rtp:<rtpsession0>
getting caps application/x-rtp, ssrc=(uint)1797986802;
application/x-rtp
0:00:00.017725985 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:2097:gst_rtp_session_request_new_pad:<rtpsession0>
requesting pad send_rtcp_src
0:00:00.017736745 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:2052:create_send_rtcp_src:<rtpsession0> creating pad
Leitung wird auf PAUSIERT gesetzt ...
/GstPipeline:pipeline0/GstAudioTestSrc:audiotestsrc0.GstPad:src: caps
= audio/x-raw-int, channels=(int)1, rate=(int)8000, width=(int)16,
depth=(int)16, endianness=(int)1234, signed=(boolean)true
Leitung ist aktiv und erfordert keinen VORLAUF …
Leitung wird auf ABSPIELEN gesetzt ...
0:00:00.018531811 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:1625:gst_rtp_session_query_send_rtcp_src:<rtpsession0>
received QUERY
0:00:00.018548241 18520      0x1e41d60 WARN                     bin
gstbin.c:2399:gst_bin_do_latency_func:<pipeline0> failed to query
latency
0:00:00.018582145 18520      0x1e41d60 DEBUG             rtpsession
gstrtpsession.c:901:start_rtcp_thread:<rtpsession0> starting RTCP
thread
New clock: GstSystemClock
0:00:00.018731280 18520      0x1e590a0 DEBUG             rtpsession
gstrtpsession.c:1682:gst_rtp_session_event_send_rtp_sink:<rtpsession0>
received event
0:00:00.018747478 18520      0x1e590a0 DEBUG             rtpsession
gstrtpsession.c:1711:gst_rtp_session_event_send_rtp_sink:<rtpsession0>
configured NEWSEGMENT update 0, rate 1,000000, applied rate 1,000000,
format GST_FORMAT_TIME, 0:00:00.000000000 -- 99:99:99.999999999, time
0:00:00.000000000, accum 0:00:00.000000000
0:00:00.018811353 18520      0x1e590a0 DEBUG             rtpsession
gstrtpsession.c:1682:gst_rtp_session_event_send_rtp_sink:<rtpsession0>
received event
/GstPipeline:pipeline0/GstALawEnc:alawenc0.GstPad:sink: caps =
audio/x-raw-int, rate=(int)8000, channels=(int)1,
endianness=(int)1234, width=(int)16, depth=(int)16,
signed=(boolean)true
/GstPipeline:pipeline0/GstALawEnc:alawenc0.GstPad:src: caps =
audio/x-alaw, rate=(int)8000, channels=(int)1
/GstPipeline:pipeline0/GstALawEnc:alawenc0.GstPad:sink: caps =
audio/x-raw-int, channels=(int)1, rate=(int)8000, width=(int)16,
depth=(int)16, endianness=(int)1234, signed=(boolean)true
0:00:00.019002271 18520      0x1e590a0 DEBUG             rtpsession
gstrtpsession.c:1775:gst_rtp_session_getcaps_send_rtp:<rtpsession0>
getting caps application/x-rtp, ssrc=(uint)1797986802;
application/x-rtp
/GstPipeline:pipeline0/GstRtpPcmaPay:rtppcmapay0.GstPad:src: caps =
application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, ssrc=(uint)1797986802, payload=(int)8,
clock-base=(uint)3002705541, seqnum-base=(uint)34956
/GstPipeline:pipeline0/GstRtpPcmaPay:rtppcmapay0.GstPad:sink: caps =
audio/x-alaw, rate=(int)8000, channels=(int)1
/GstPipeline:pipeline0/GstRtpPcmaPay:rtppcmapay0: timestamp = 3002705542
/GstPipeline:pipeline0/GstRtpPcmaPay:rtppcmapay0: seqnum = 34956
0:00:00.019198514 18520      0x1e590a0 DEBUG             rtpsession
gstrtpsession.c:1794:gst_rtp_session_setcaps_send_rtp:<rtpsession0>
setting internal SSRC to 6b2b19f2
/GstPipeline:pipeline0/GstRtpBin:rtpbin/GstRtpSession:rtpsession0.GstPad:send_rtp_sink:
caps = application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, ssrc=(uint)1797986802, payload=(int)8,
clock-base=(uint)3002705541, seqnum-base=(uint)34956
/GstPipeline:pipeline0/GstRtpBin:rtpbin.GstGhostPad:send_rtp_sink_0:
caps = application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, ssrc=(uint)1797986802, payload=(int)8,
clock-base=(uint)3002705541, seqnum-base=(uint)34956
/GstPipeline:pipeline0/GstRtpBin:rtpbin.GstGhostPad:send_rtp_sink_0.GstProxyPad:proxypad1:
caps = application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, ssrc=(uint)1797986802, payload=(int)8,
clock-base=(uint)3002705541, seqnum-base=(uint)34956
0:00:00.019346617 18520      0x1e590a0 LOG               rtpsession
gstrtpsession.c:1819:gst_rtp_session_chain_send_rtp_common:<rtpsession0>
received RTP packet
0:00:00.019362869 18520      0x1e590a0 LOG               rtpsession
rtpsession.c:2500:rtp_session_send_rtp: received RTP packet for
sending
0:00:00.019383895 18520      0x1e590a0 LOG               rtpsession
rtpsession.c:1211:source_push_rtp: source 6b2b19f2 pushed sender RTP
packet
0:00:00.019396929 18520      0x1e590a0 LOG               rtpsession
gstrtpsession.c:1078:gst_rtp_session_send_rtp:<rtpsession0> sending
RTP packet
/GstPipeline:pipeline0/GstRtpBin:rtpbin.GstGhostPad:send_rtp_src_0:
caps = application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, ssrc=(uint)1797986802, payload=(int)8,
clock-base=(uint)3002705541, seqnum-base=(uint)34956
/GstPipeline:pipeline0/GstRtpBin:rtpbin/GstRtpSession:rtpsession0.GstPad:send_rtp_src:
caps = application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, ssrc=(uint)1797986802, payload=(int)8,
clock-base=(uint)3002705541, seqnum-base=(uint)34956
/GstPipeline:pipeline0/GstUDPSink:udpsink0.GstPad:sink: caps =
application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, ssrc=(uint)1797986802, payload=(int)8,
clock-base=(uint)3002705541, seqnum-base=(uint)34956
/GstPipeline:pipeline0/GstRtpBin:rtpbin.GstGhostPad:send_rtp_src_0.GstProxyPad:proxypad2:
caps = application/x-rtp, media=(string)audio, clock-rate=(int)8000,
encoding-name=(string)PCMA, ssrc=(uint)1797986802, payload=(int)8,
clock-base=(uint)3002705541, seqnum-base=(uint)34956
0:00:00.019675320 18520      0x1e590f0 DEBUG             rtpsession
gstrtpsession.c:833:rtcp_thread:<rtpsession0> entering RTCP thread
0:00:00.019701693 18520      0x1e590f0 DEBUG             rtpsession
gstrtpsession.c:843:rtcp_thread:<rtpsession0> starting at
6:19:38.239541917
0:00:00.019707519 18520      0x1e590f0 DEBUG             rtpsession
rtpsession.c:2724:rtp_session_next_timeout: current time:
6:19:38.239541917, next time: 0:00:00.000000000
0:00:00.019722134 18520      0x1e590f0 DEBUG             rtpsession
gstrtpsession.c:853:rtcp_thread:<rtpsession0> next check time
0:00:00.000000000
0:00:00.019747652 18520      0x1e590f0 DEBUG             rtpsession
gstrtpsession.c:881:rtcp_thread:<rtpsession0> unlocked 1, current
6:19:38.239584629
0:00:00.019782018 18520      0x1e590f0 DEBUG             rtpsession
rtpsession.c:3118:rtp_session_on_timeout: reporting at
6:19:38.239584629, NTP time 990276:10:47.141082000
0:00:00.019792602 18520 0x7f1c780028a0 DEBUG             rtpsession
gstrtpsession.c:1625:gst_rtp_session_query_send_rtcp_src:<rtpsession0>
received QUERY
0:00:00.019801284 18520      0x1e590f0 DEBUG             rtpsession
rtpsession.c:2573:calculate_rtcp_interval: next deterministic
interval: 0:00:02.500000000, first 1
0:00:00.019897889 18520 0x7f1c780028a0 DEBUG             rtpsession
gstrtpsession.c:1654:gst_rtp_session_event_send_rtcp_src:<rtpsession0>
received EVENT
0:00:00.019906572 18520      0x1e590f0 DEBUG             rtpsession
rtpsession.c:2578:calculate_rtcp_interval: next interval:
0:00:02.500000000
0:00:00.019960553 18520      0x1e590f0 LOG               rtpsession
rtpsession.c:2858:session_cleanup: timeout base interval
0:00:02.500000000
0:00:00.019960959 18520 0x7f1c780028a0 WARN                     bin
gstbin.c:2395:gst_bin_do_latency_func:<pipeline0> did not really
configure latency of 0:00:00.000000000
0:00:00.019982243 18520      0x1e590f0 DEBUG             rtpsession
rtpsession.c:2573:calculate_rtcp_interval: next deterministic
interval: 0:00:05.000000000, first 0
0:00:00.020021490 18520      0x1e590f0 DEBUG             rtpsession
rtpsession.c:2578:calculate_rtcp_interval: next interval:
0:00:04.618856934
0:00:00.020033805 18520      0x1e590f0 DEBUG             rtpsession
rtpsession.c:3049:is_rtcp_time: can send RTCP now, next interval
0:00:04.618856934
0:00:00.020056723 18520      0x1e590f0 DEBUG             rtpsession
rtpsession.c:2759:session_start_rtcp: create SR for SSRC 6b2b19f2
_______________________________________________
gstreamer-devel mailing list
[hidden email]
http://lists.freedesktop.org/mailman/listinfo/gstreamer-devel