Project: webrtc Issues People Development process History Sign in
New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.
Starred by 7 users
Status: Untriaged
Owner: ----
Cc:
Components:
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment
onaddstream callback doesn't fire until after SetRD success callback
Project Member Reported by juberti@webrtc.org, May 16 2014 Back to list
By spec, all offered streams must fire their onaddstream callbacks before the success callback is fired for setRemoteDescription. However, in Chrome 36 (and possibly earlier), onaddstream fires after the success callback. As a result, it's not possible to know when you have been notified of all remote streams, and this requires some hacking in AppRTC to distinguish a/v vs audio-only cases.
 
Weirdly, I only see this in AppRTC on prod, not when I run AppRTC locally, or any of the local demos.

AppRTC log:
This appears to be Chrome adapter.js:123
1.023: Initializing; room=52869388. adapter.js:13
1.026: Opening channel. adapter.js:13
1.056: Requested access to local media with mediaConstraints:
  '{"audio":true,"video":{"optional":[],"mandatory":{"minWidth":"1280","minHeight":"720"}}}' adapter.js:13
1.192: User has granted access to local media. adapter.js:13
1.606: Channel opened. adapter.js:13
1.607: Creating PeerConnection. adapter.js:13
1.609: Created RTCPeerConnnection with:
  config: '{"iceServers":[{"urls":"stun:stun.l.google.com:19302"},{"urls":["turn:23.236.53.1:3478?transport=udp","turn:23.236.53.1:3478?transport=tcp","turn:23.236.53.1:3479?transport=udp","turn:23.236.53.1:3479?transport=tcp"],"credential":"zS/cEwZdtjRjZ5D6CdOp4zNAriQ=","username":"1400359957:53282835"}]}';
  constraints: '{"optional":[{"googImprovedWifiBwe":true},{"DtlsSrtpKeyAgreement":false}]}'. adapter.js:13
1.610: Adding local stream. adapter.js:13
1.611: Sending offer to peer, with constraints: 
  '{"optional":[{"VoiceActivityDetection":false}],"mandatory":{"OfferToReceiveAudio":true,"OfferToReceiveVideo":true}}'. adapter.js:13
1.616: Prefer audio receive codec: opus/48000 adapter.js:13
1.633: C->S: {"sdp":"v=0\r\no=- 4221363400444669773 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE audio video\r\na=msid-semantic: WMS 3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY\r\nm=audio 1 RTP/SAVPF 111 103 104 0 8 126\r\nc=IN IP4 0.0.0.0\r\na=rtcp:1 IN IP4 0.0.0.0\r\na=ice-ufrag:9XGSZ0H5OIYvFPUr\r\na=ice-pwd:P+kezinlcgy8LN6NRE79SnWe\r\na=ice-options:google-ice\r\na=mid:audio\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=sendrecv\r\na=rtcp-mux\r\na=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:Nk4EC3Lk9wSQ3EkbjiJh6yK+0jFr2w1hdv0c7q7S\r\na=rtpmap:111 opus/48000/2\r\na=fmtp:111 minptime=10\r\na=rtpmap:103 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:126 telephone-event/8000\r\na=maxptime:60\r\na=ssrc:271309751 cname:020vJGWRbDPCjOzX\r\na=ssrc:271309751 msid:3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY 53cf9918-c22d-4763-bc89-78dd0ed8b3c6\r\na=ssrc:271309751 mslabel:3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY\r\na=ssrc:271309751 label:53cf9918-c22d-4763-bc89-78dd0ed8b3c6\r\nm=video 1 RTP/SAVPF 100 116 117\r\nc=IN IP4 0.0.0.0\r\na=rtcp:1 IN IP4 0.0.0.0\r\na=ice-ufrag:9XGSZ0H5OIYvFPUr\r\na=ice-pwd:P+kezinlcgy8LN6NRE79SnWe\r\na=ice-options:google-ice\r\na=mid:video\r\na=extmap:2 urn:ietf:params:rtp-hdrext:toffset\r\na=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=sendrecv\r\na=rtcp-mux\r\na=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:Nk4EC3Lk9wSQ3EkbjiJh6yK+0jFr2w1hdv0c7q7S\r\na=rtpmap:100 VP8/90000\r\na=rtcp-fb:100 ccm fir\r\na=rtcp-fb:100 nack\r\na=rtcp-fb:100 nack pli\r\na=rtcp-fb:100 goog-remb\r\na=rtpmap:116 red/90000\r\na=rtpmap:117 ulpfec/90000\r\na=ssrc:2171529068 cname:020vJGWRbDPCjOzX\r\na=ssrc:2171529068 msid:3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY 99765aae-9ede-489e-a220-f5243516ecd0\r\na=ssrc:2171529068 mslabel:3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY\r\na=ssrc:2171529068 label:99765aae-9ede-489e-a220-f5243516ecd0\r\n","type":"offer"} adapter.js:13
1.649: Set session description success. adapter.js:13
1.658: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3028412780 1 udp 2122194687 172.31.1.167 53538 typ host generation 0\r\n"} adapter.js:13
1.660: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3028412780 2 udp 2122194687 172.31.1.167 53538 typ host generation 0\r\n"} adapter.js:13
1.662: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3028412780 1 udp 2122194687 172.31.1.167 53538 typ host generation 0\r\n"} adapter.js:13
1.663: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3028412780 2 udp 2122194687 172.31.1.167 53538 typ host generation 0\r\n"} adapter.js:13
1.751: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:4194440604 1 tcp 1518214911 172.31.1.167 0 typ host generation 0\r\n"} adapter.js:13
1.752: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:4194440604 2 tcp 1518214911 172.31.1.167 0 typ host generation 0\r\n"} adapter.js:13
1.752: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:4194440604 1 tcp 1518214911 172.31.1.167 0 typ host generation 0\r\n"} adapter.js:13
1.753: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:4194440604 2 tcp 1518214911 172.31.1.167 0 typ host generation 0\r\n"} adapter.js:13
1.821: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:1116836024 1 udp 1685987071 74.125.59.65 36291 typ srflx raddr 172.31.1.167 rport 53538 generation 0\r\n"} adapter.js:13
1.822: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:1116836024 2 udp 1685987071 74.125.59.65 36291 typ srflx raddr 172.31.1.167 rport 53538 generation 0\r\n"} adapter.js:13
1.823: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3671762466 1 udp 41819903 23.236.53.1 57475 typ relay raddr 74.125.59.65 rport 36291 generation 0\r\n"} adapter.js:13
1.823: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3671762466 2 udp 41819903 23.236.53.1 57475 typ relay raddr 74.125.59.65 rport 36291 generation 0\r\n"} adapter.js:13
1.824: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:1116836024 1 udp 1685987071 74.125.59.65 36291 typ srflx raddr 172.31.1.167 rport 53538 generation 0\r\n"} adapter.js:13
1.824: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:1116836024 2 udp 1685987071 74.125.59.65 36291 typ srflx raddr 172.31.1.167 rport 53538 generation 0\r\n"} adapter.js:13
1.825: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3671762466 1 udp 41819903 23.236.53.1 57475 typ relay raddr 74.125.59.65 rport 36291 generation 0\r\n"} adapter.js:13
1.826: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3671762466 2 udp 41819903 23.236.53.1 57475 typ relay raddr 74.125.59.65 rport 36291 generation 0\r\n"} adapter.js:13
2.319: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3671762466 1 udp 25042687 23.236.53.1 56637 typ relay raddr 74.125.59.65 rport 12466 generation 0\r\n"} adapter.js:13
2.320: C->S: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3671762466 2 udp 25042687 23.236.53.1 56637 typ relay raddr 74.125.59.65 rport 12466 generation 0\r\n"} adapter.js:13
2.321: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3671762466 1 udp 25042687 23.236.53.1 56637 typ relay raddr 74.125.59.65 rport 12466 generation 0\r\n"} adapter.js:13
2.322: C->S: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3671762466 2 udp 25042687 23.236.53.1 56637 typ relay raddr 74.125.59.65 rport 12466 generation 0\r\n"} adapter.js:13
2.776: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3028412780 1 udp 2122194687 172.31.1.167 53538 typ host generation 0\r\n"} adapter.js:13
2.777: Remote candidate added successfully. adapter.js:13
2.779: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3671762466 1 udp 25042687 23.236.53.1 56637 typ relay raddr 74.125.59.65 rport 12466 generation 0\r\n"} adapter.js:13
2.780: Remote candidate added successfully. adapter.js:13
2.826: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3671762466 2 udp 25042687 23.236.53.1 56637 typ relay raddr 74.125.59.65 rport 12466 generation 0\r\n"} adapter.js:13
2.826: Remote candidate added successfully. adapter.js:13
2.848: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:4194440604 2 tcp 1518214911 172.31.1.167 0 typ host generation 0\r\n"} adapter.js:13
2.849: Remote candidate added successfully. adapter.js:13
2.873: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3671762466 1 udp 25042687 23.236.53.1 56637 typ relay raddr 74.125.59.65 rport 12466 generation 0\r\n"} adapter.js:13
2.874: Remote candidate added successfully. adapter.js:13
2.916: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3671762466 2 udp 25042687 23.236.53.1 56637 typ relay raddr 74.125.59.65 rport 12466 generation 0\r\n"} adapter.js:13
2.917: Remote candidate added successfully. adapter.js:13
2.930: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3671762466 1 udp 41819903 23.236.53.1 57475 typ relay raddr 74.125.59.65 rport 36291 generation 0\r\n"} adapter.js:13
2.930: Remote candidate added successfully. adapter.js:13
3.003: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:1116836024 2 udp 1685987071 74.125.59.65 36291 typ srflx raddr 172.31.1.167 rport 53538 generation 0\r\n"} adapter.js:13
3.004: Remote candidate added successfully. adapter.js:13
3.080: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3028412780 2 udp 2122194687 172.31.1.167 53538 typ host generation 0\r\n"} adapter.js:13
3.081: Remote candidate added successfully. adapter.js:13
3.160: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:3671762466 2 udp 41819903 23.236.53.1 57475 typ relay raddr 74.125.59.65 rport 36291 generation 0\r\n"} adapter.js:13
3.161: Remote candidate added successfully. adapter.js:13
3.241: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3028412780 1 udp 2122194687 172.31.1.167 53538 typ host generation 0\r\n"} adapter.js:13
3.242: Remote candidate added successfully. adapter.js:13
3.322: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3671762466 2 udp 41819903 23.236.53.1 57475 typ relay raddr 74.125.59.65 rport 36291 generation 0\r\n"} adapter.js:13
3.322: Remote candidate added successfully. adapter.js:13
3.409: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:1116836024 1 udp 1685987071 74.125.59.65 36291 typ srflx raddr 172.31.1.167 rport 53538 generation 0\r\n"} adapter.js:13
3.409: Remote candidate added successfully. adapter.js:13
3.490: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:4194440604 1 tcp 1518214911 172.31.1.167 0 typ host generation 0\r\n"} adapter.js:13
3.490: Remote candidate added successfully. adapter.js:13
3.561: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3671762466 1 udp 41819903 23.236.53.1 57475 typ relay raddr 74.125.59.65 rport 36291 generation 0\r\n"} adapter.js:13
3.562: Remote candidate added successfully. adapter.js:13
3.638: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:1116836024 1 udp 1685987071 74.125.59.65 36291 typ srflx raddr 172.31.1.167 rport 53538 generation 0\r\n"} adapter.js:13
3.638: Remote candidate added successfully. adapter.js:13
3.716: S->C: {"type":"candidate","label":0,"id":"audio","candidate":"a=candidate:4194440604 2 tcp 1518214911 172.31.1.167 0 typ host generation 0\r\n"} adapter.js:13
3.716: Remote candidate added successfully. adapter.js:13
3.792: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:3028412780 2 udp 2122194687 172.31.1.167 53538 typ host generation 0\r\n"} adapter.js:13
3.792: Remote candidate added successfully. adapter.js:13
3.869: S->C: {"sdp":"v=0\r\no=- 4221363400444669773 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE audio video\r\na=msid-semantic: WMS 3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY\r\nm=audio 1 RTP/SAVPF 111 103 104 0 8 126\r\nc=IN IP4 0.0.0.0\r\na=rtcp:1 IN IP4 0.0.0.0\r\na=ice-ufrag:9XGSZ0H5OIYvFPUr\r\na=ice-pwd:P+kezinlcgy8LN6NRE79SnWe\r\na=mid:audio\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=sendrecv\r\na=rtcp-mux\r\na=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:Nk4EC3Lk9wSQ3EkbjiJh6yK+0jFr2w1hdv0c7q7S\r\na=rtpmap:111 opus/48000/2\r\na=fmtp:111 minptime=10\r\na=rtpmap:103 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:126 telephone-event/8000\r\na=maxptime:60\r\na=ssrc:271309751 cname:020vJGWRbDPCjOzX\r\na=ssrc:271309751 msid:3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY 53cf9918-c22d-4763-bc89-78dd0ed8b3c6\r\na=ssrc:271309751 mslabel:3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY\r\na=ssrc:271309751 label:53cf9918-c22d-4763-bc89-78dd0ed8b3c6\r\nm=video 1 RTP/SAVPF 100 116 117\r\nc=IN IP4 0.0.0.0\r\na=rtcp:1 IN IP4 0.0.0.0\r\na=ice-ufrag:9XGSZ0H5OIYvFPUr\r\na=ice-pwd:P+kezinlcgy8LN6NRE79SnWe\r\na=mid:video\r\na=extmap:2 urn:ietf:params:rtp-hdrext:toffset\r\na=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=sendrecv\r\na=rtcp-mux\r\na=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:Nk4EC3Lk9wSQ3EkbjiJh6yK+0jFr2w1hdv0c7q7S\r\na=rtpmap:100 VP8/90000\r\na=rtcp-fb:100 ccm fir\r\na=rtcp-fb:100 nack\r\na=rtcp-fb:100 nack pli\r\na=rtcp-fb:100 goog-remb\r\na=rtpmap:116 red/90000\r\na=rtpmap:117 ulpfec/90000\r\na=ssrc:2171529068 cname:020vJGWRbDPCjOzX\r\na=ssrc:2171529068 msid:3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY 99765aae-9ede-489e-a220-f5243516ecd0\r\na=ssrc:2171529068 mslabel:3BL2t03SuUIOLMW9xMJEZN2gFEMliQqZEjeY\r\na=ssrc:2171529068 label:99765aae-9ede-489e-a220-f5243516ecd0\r\n","type":"answer"} adapter.js:13
3.869: No preference on audio send codec. adapter.js:13
3.884: Set remote session description success. adapter.js:13
3.885: Remote stream added. adapter.js:13
3.941: S->C: {"type":"candidate","label":1,"id":"video","candidate":"a=candidate:4194440604 1 tcp 1518214911 172.31.1.167 0 typ host generation 0\r\n"} adapter.js:13
3.942: Remote candidate added successfully. 
Project Member Comment 2 by juberti@webrtc.org, May 16 2014
Observed in 37.0.1993.0 canary, with https://apprtc.appspot.com/?r=52869388&debug=loopback
Project Member Comment 3 by juberti@webrtc.org, May 16 2014
And even more oddly, webrtc-internals reports that the onaddstream does come first.

5/16/2014 1:56:47 PM	
setRemoteDescription
5/16/2014 1:56:47 PM	
signalingStateChange
SignalingStateStable
5/16/2014 1:56:47 PM	
onAddStream
label: N9rUruztWHi7yaqeeutKs0L2wjI2BTAs8RkK, audio: [f138d61f-67d7-4134-9902-62c42cec4aa3], video: [c939f223-f25d-4dc4-92bb-5771a8361e7c]
5/16/2014 1:56:47 PM	setRemoteDescriptionOnSuccess
Project Member Comment 4 by juberti@webrtc.org, May 22 2014
Cc: pthatcher@webrtc.org
This doesn't always happen. It seems to be very timing-dependent; doesn't occur on local AppRTC, but does happen on prod AppRTC.

pthatcher, this would be a good bugfix to look at to get your hands dirty with Chrome.
Cc: -pthatcher@webrtc.org wu@webrtc.org
Owner: pthatcher@webrtc.org
So assign to Peter?
Project Member Comment 6 by juberti@webrtc.org, May 29 2014
yes
Project Member Comment 7 by pthatcher@google.com, Jun 9 2014
Labels: -Pri-2 Pri-1
Project Member Comment 8 by vikasmarwaha@webrtc.org, Aug 12 2014
Peter, should is this done for M37?
Comment 9 by vrk@webrtc.org, Oct 16 2014
Labels: -Mstone-37 Mstone-41 ent
Comment 10 by vrk@webrtc.org, Oct 16 2014
Labels: -ent EngTriaged
Project Member Comment 11 by pthatcher@webrtc.org, Jan 7 2015
Labels: -Mstone-41 Mstone-42
Project Member Comment 12 by pthatcher@webrtc.org, Feb 19 2015
Labels: -Mstone-42 Mstone-44
This looks like it's not hitting m42.  Update it if I'm wrong.
Project Member Comment 13 by tnakamura@webrtc.org, Feb 17 2016
Cc: -wu@webrtc.org hta@webrtc.org
Labels: -Mstone-44 Mstone-50
Is this still a valid issue?
I can reproduce this but for device-to-device calls only. During, upgrade from audio-only call to audio-video call, onAddStream is not invoked.
Hi, I changed the label for SDP and media tracks (audio/video) in every negotiation and now the things are working as expected!
FYI!
Project Member Comment 16 by kjellander@webrtc.org, Oct 5 2016
Labels: M-50
Project Member Comment 17 by anatolid@webrtc.org, Oct 17 2016
Can this be closed based on #14?
Project Member Comment 18 by deadbeef@webrtc.org, Oct 18 2016
Cc: pthatcher@webrtc.org
Labels: -Mstone-50 -EngTriaged -Pri-1 -M-50 Spec-W3C Pri-3
Owner: tommi@webrtc.org
I still see the issue with AppRTC in loopback mode. And I checked that it's not because AppRTC itself is doing anything to delay onaddstream. However I think the priority of this can be lowered. It doesn't seem to have affected anyone, and it hasn't been fixed in 2 years.

Anyway, I think what's going on is that both SRD's OnSuccess and the OnAddStream callback queue a task on the main thread. But OnAddStream schedules an extra task: https://cs.chromium.org/chromium/src/third_party/WebKit/Source/modules/peerconnection/RTCPeerConnection.cpp?sq=package:chromium&rcl=1476717412&l=1322

Understanding the interactions between various task queues in Chrome seems beyond our team though. tommi, would you be able to triage this?
Project Member Comment 19 by deadbeef@webrtc.org, Oct 28 2016
Status: Untriaged
Project Member Comment 20 by deadbeef@webrtc.org, Nov 10 2016
Owner: guidou@webrtc.org
It looks like guidou@ is responsible for "PeerConnection/GetUserMedia in Chrome" triage, my mistake.
Project Member Comment 21 by anatolid@chromium.org, Dec 15 2016
Cc: guidou@webrtc.org
Components: -PeerConnection GetUserMedia
Owner: ----
Sign in to add a comment