Re: chrome to firefox call fails when browsers behind different NAT devices and trickle ICE is used.

Byron Campen Tue, 18 Nov 2014 10:47:11 -0800

We are never seeing a candidate from the other side, nor do weappear to be receiving STUN checks.


Best regards,
Byron Campen


On 11/17/14 10:48 AM, Frank Coco wrote:

On Monday, November 17, 2014 11:34:28 AM UTC-5, Frank Coco wrote:

I am having an issue in the following call flow when trickle ICE is used.

Chrome ---- NAT ------ Media-gateway ---- NAT ---- Firefox



Basically the call fails because Firefox doesn't respond to the Media gateway's 
STUN Requests.

I see the following failure in the Firefox logs:
"ICE failed, see about:webrtc for more details"


I couldn't find any details as to why the failure occurred. I'm including the 
full log below.

Thanks for the help,
Frank.



[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: setTimeout

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: get

[WEBDRIVER] [INFO] [fxdriver.wdSession] setWaitForPageLoad false

[WEBDRIVER] [INFO] [fxdriver.wdSession] setWaitForPageLoad true

[WEBDRIVER] [INFO] [fxdriver.badCertListener] Found preference for 
webdriver_accept_untrusted_certs: true

[WEBDRIVER] [INFO] [fxdriver.WdCertOverrideService] Allowing certificate from 
site: 172.30.12.109:7002

[WEBDRIVER] [INFO] [fxdriver.WdCertOverrideService] Setting all Override Bits

[WEBDRIVER] [INFO] [fxdriver.WdCertOverrideService] Override Bits: 7

[WEBDRIVER] [INFO] [fxdriver.badCertListener] Found preference for 
webdriver_accept_untrusted_certs: true

[WEBDRIVER] [INFO] [fxdriver.WdCertOverrideService] Allowing certificate from 
site: 172.30.12.109:7002

[WEBDRIVER] [INFO] [fxdriver.WdCertOverrideService] Setting all Override Bits

[WEBDRIVER] [INFO] [fxdriver.WdCertOverrideService] Override Bits: 7

The character encoding of the HTML document was not declared. The document will 
render with garbled text in some browser configurations if the document 
contains characters from outside the US-ASCII range. The character encoding of 
the page must be declared in the document or in the transfer protocol. 
sample_call.html
"wsc-call initialized." wsc-call.js:2
[WEBDRIVER] [INFO] [fxdriver.PatientListener] request status is 0

GET https://172.30.12.109:7002/favicon.ico [HTTP/1.1 404 Not Found 0ms]
GET https://172.30.12.109:7002/favicon.ico [HTTP/1.1 404 Not Found 16ms]
[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: setTimeout

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: findElement

Use of getAttributeNode() is deprecated. Use getAttribute() instead. 
driver-component.js:7515
[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementTagName

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
sendKeysToElement

[WEBDRIVER] [INFO] [fxdriver.WebElement] Need to switch focus

[WEBDRIVER] [INFO] [fxdriver.Utils] Pending native events: false

[WEBDRIVER] [INFO] [fxdriver.Utils] Extra events processed: 0 Page Unloaded: 
false

[WEBDRIVER] [INFO] [fxdriver.Utils] Done main loop.

[WEBDRIVER] [INFO] [fxdriver.Utils] Done extra event loop, 7

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: setTimeout

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: findElement

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementTagName

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: clickElement

[WEBDRIVER] [INFO] [fxdriver.WebElement] Using native events for click

[WEBDRIVER] [INFO] [fxdriver.Utils] Browser-specific offset (X,Y): 0, 79

[WEBDRIVER] [INFO] [fxdriver.Utils] Pending native events: false

[WEBDRIVER] [INFO] [fxdriver.Utils] Extra events processed: 0 Page Unloaded: 
false

[WEBDRIVER] [INFO] [fxdriver.Utils] Done main loop.

[WEBDRIVER] [INFO] [fxdriver.Utils] Done extra event loop, 24

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: setTimeout

"2014-11-12 14:20:00 [wsc Debug 
line:wsc</h@https://172.30.12.109:7002/api/wsc-common.js:3:205]"; wsc-common.js:2
"creating the websocket..." wsc-common.js:2
[WEBDRIVER] [INFO] [fxdriver.Utils] Done native event wait.

"2014-11-12 14:20:00 [wsc Debug:]" wsc-common.js:2
"websocket event handler onopen is invoked." wsc-common.js:2
[WEBDRIVER] [INFO] [fxdriver.Utils] Done native event wait.

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: findElement

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementTagName

"2014-11-12 14:20:00 [wsc Debug 
line:i@https://172.30.12.109:7002/api/wsc-common.js:2:21578]"; wsc-common.js:2
"New IPs: 192.168.1.3, Old IPs: " wsc-common.js:2
"2014-11-12 14:20:00 [wsc Debug 
line:wsc</d.sendRegister@https://172.30.12.109:7002/api/wsc-common.js:3:12165]"; 
wsc-common.js:2
"Send message: {
     "control": {
         "type": "request",
         "package_type": "register",
         "sequence": 1,
         "version": "1.0"
     },
     "header": {
         "action": "connect",
         "initiator": "[email protected]",
         "target": "[email protected]"
     },
     "payload": {}
}" wsc-common.js:2
"2014-11-12 14:20:00 [wsc Debug 
line:wsc</h.prototype.sendMessage@https://172.30.12.109:7002/api/wsc-common.js:3:4725]";
 wsc-common.js:2
"addMessage - cslw: 1,csuw: 1" wsc-common.js:2
[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementText

"2014-11-12 14:20:00 [wsc Debug 
line:wsc</d.initWebSocket/a.wscWebsocket.onmessage@https://172.30.12.109:7002/api/wsc-common.js:3:11497]";
 wsc-common.js:2
"Received data from server: {
     "header": {
         "initiator": "[email protected]",
         "target": "[email protected]",
         "action": "connect"
     },
     "control": {
         "session_id": "pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "ack_sequence": 1,
         "package_type": "register",
         "sequence": 1,
         "message_state": "final",
         "subsession_id": "s-register-pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "type": "response",
         "correlation_id": "c1",
         "version": "1.0"
     }
}" wsc-common.js:2
"2014-11-12 14:20:00 [wsc Debug 
line:wsc</d.handleWsData@https://172.30.12.109:7002/api/wsc-common.js:3:10130]"; 
wsc-common.js:2
"ackMessages - cslw: 2,csuw: 1" wsc-common.js:2
"2014-11-12 14:20:00 [wsc Debug 
line:wsc</c.Message.prototype.ack@https://172.30.12.109:7002/api/wsc-common.js:2:18994]";
 wsc-common.js:2
"Send message: {
     "control": {
         "type": "acknowledgement",
         "package_type": "register",
         "session_id": "pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "subsession_id": "s-register-pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "sequence": 1,
         "version": "1.0"
     },
     "header": {},
     "payload": {}
}" wsc-common.js:2
"2014-11-12 14:20:00 [wsc Debug 
line:wsc</k.prototype.onMessage@https://172.30.12.109:7002/api/wsc-common.js:3:16226]";
 wsc-common.js:2
"PeriodlyACKChecker ack the message in sequence 1" wsc-common.js:2
[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementText

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: setTimeout

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: findElement

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementTagName

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
isElementSelected

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: clickElement

[WEBDRIVER] [INFO] [fxdriver.WebElement] Using native events for click

[WEBDRIVER] [INFO] [fxdriver.Utils] Browser-specific offset (X,Y): 0, 79

[WEBDRIVER] [INFO] [fxdriver.Utils] Pending native events: false

[WEBDRIVER] [INFO] [fxdriver.Utils] Extra events processed: 0 Page Unloaded: 
false

[WEBDRIVER] [INFO] [fxdriver.Utils] Done main loop.

[WEBDRIVER] [INFO] [fxdriver.Utils] Done extra event loop, 9

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: setTimeout

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: findElement

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementTagName

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
sendKeysToElement

[WEBDRIVER] [INFO] [fxdriver.WebElement] Need to switch focus

[WEBDRIVER] [INFO] [fxdriver.Utils] Done native event wait.

[WEBDRIVER] [INFO] [fxdriver.Utils] Pending native events: false

[WEBDRIVER] [INFO] [fxdriver.Utils] Extra events processed: 0 Page Unloaded: 
false

[WEBDRIVER] [INFO] [fxdriver.Utils] Done main loop.

[WEBDRIVER] [INFO] [fxdriver.Utils] Done extra event loop, 6

[WEBDRIVER] [INFO] [fxdriver.Utils] Done native event wait.

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: setTimeout

"2014-11-12 14:20:04 [wsc Debug 
line:wsc</d.initWebSocket/a.wscWebsocket.onmessage@https://172.30.12.109:7002/api/wsc-common.js:3:11497]";
 wsc-common.js:2
"Received data from server: {
     "payload": {
         "sdp": "v=0\r\no=- 4367238177690043858 2 IN IP4 127.0.0.1\r\ns=Acme\r\nt=0 
0\r\nm=audio 1 RTP/SAVPF 111 103 104 0 8 106 105 13 126\r\nc=IN IP4 0.0.0.0\r\na=rtpmap:111 
opus/48000/2\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:106 CN/32000\r\na=rtpmap:105 CN/16000\r\na=rtpmap:13 
CN/8000\r\na=rtpmap:126 telephone-event/8000\r\na=fingerprint:sha-256 
EF:84:6D:55:1B:51:AB:D0:8C:38:28:B3:42:04:5E:A9:8E:33:4F:B3:DD:7D:D4:FA:A0:26:26:49:70:E3:CC:F3\r\na=setup:actpass\r\na=ssrc:2082117451
 cname:eEq/1Whxvz1xr3TL\r\na=ssrc:2082117451 msid:3Kdlj0Th0d3zo15YjqjKq29rpftDoCirEzvl 
bfc1a414-47d4-4e6d-919e-e1be2eb75df2\r\na=ssrc:2082117451 
mslabel:3Kdlj0Th0d3zo15YjqjKq29rpftDoCirEzvl\r\na=ssrc:2082117451 
label:bfc1a414-47d4-4e6d-919e-e1be2eb75df2\r\na=ice-ufrag:L4/sSx9NYyi7thsr\r\na=ice-pwd:htXLlfwB1Mkc1wBHokQAvWLi\r\na=ice-options:trickle\r\na=rtcp:22513
 IN IP4 172.30.12.136\r\na=sendrecv\r\n"
     },
     "header": {
         "initiator": "[email protected]",
         "target": "[email protected]",
         "action": "start"
     },
     "control": {
         "session_id": "pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "package_type": "call",
         "sequence": 2,
         "subsession_id": 
"[email protected]",
         "type": "request",
         "correlation_id": "s1",
         "version": "1.0"
     }
}" wsc-common.js:2
"2014-11-12 14:20:04 [wsc Debug 
line:wsc</l.prototype.onMessage@https://172.30.12.109:7002/api/wsc-call.js:2:15693]"; 
wsc-common.js:2
"The SDP in the request is :

v=0

o=- 4367238177690043858 2 IN IP4 127.0.0.1

s=Acme

t=0 0

m=audio 1 RTP/SAVPF 111 103 104 0 8 106 105 13 126

c=IN IP4 0.0.0.0

a=rtpmap:111 opus/48000/2

a=rtpmap:103 ISAC/16000

a=rtpmap:104 ISAC/32000

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:106 CN/32000


a=rtpmap:105 CN/16000

a=rtpmap:13 CN/8000

a=rtpmap:126 telephone-event/8000

a=fingerprint:sha-256 
EF:84:6D:55:1B:51:AB:D0:8C:38:28:B3:42:04:5E:A9:8E:33:4F:B3:DD:7D:D4:FA:A0:26:26:49:70:E3:CC:F3

a=setup:actpass

a=ssrc:2082117451 cname:eEq/1Whxvz1xr3TL

a=ssrc:2082117451 msid:3Kdlj0Th0d3zo15YjqjKq29rpftDoCirEzvl 
bfc1a414-47d4-4e6d-919e-e1be2eb75df2

a=ssrc:2082117451 mslabel:3Kdlj0Th0d3zo15YjqjKq29rpftDoCirEzvl

a=ssrc:2082117451 label:bfc1a414-47d4-4e6d-919e-e1be2eb75df2

a=ice-ufrag:L4/sSx9NYyi7thsr

a=ice-pwd:htXLlfwB1Mkc1wBHokQAvWLi

a=ice-options:trickle

a=rtcp:22513 IN IP4 172.30.12.136

a=sendrecv

" wsc-common.js:2
"2014-11-12 14:20:04 [wsc Debug 
line:wsc</d.doRequest@https://172.30.12.109:7002/api/wsc-common.js:3:18736]"; 
wsc-common.js:2
"=== doStartCallRequest ===" wsc-common.js:2
"2014-11-12 14:20:04 [wsc Debug 
line:c@https://172.30.12.109:7002/api/wsc-common.js:3:17639]"; wsc-common.js:2
"Trying to update offer-answer state to : Offer received" wsc-common.js:2
"2014-11-12 14:20:04 [wsc Debug 
line:wsc</j.prototype.putCall@https://172.30.12.109:7002/api/wsc-call.js:2:5070]"; 
wsc-common.js:2
"use busyPingInterval 3000" wsc-common.js:2
"2014-11-12 14:20:04 [wsc Debug 
line:wsc</e.send180Ringing@https://172.30.12.109:7002/api/wsc-common.js:3:29273]"; 
wsc-common.js:2
"Send message: {
     "control": {
         "type": "response",
         "package_type": "call",
         "session_id": "pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "subsession_id": 
"[email protected]",
         "sequence": 2,
         "message_state": "subsequent",
         "correlation_id": "s1",
         "ack_sequence": 2,
         "version": "1.0"
     },
     "header": {
         "action": "start",
         "initiator": "[email protected]",
         "target": "[email protected]"
     },
     "payload": {}
}" wsc-common.js:2
"2014-11-12 14:20:04 [wsc Debug 
line:wsc</h.prototype.sendMessage@https://172.30.12.109:7002/api/wsc-common.js:3:4725]";
 wsc-common.js:2
"addMessage - cslw: 2,csuw: 2" wsc-common.js:2
[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: findElement

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementTagName

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: clickElement

[WEBDRIVER] [INFO] [fxdriver.WebElement] Using native events for click

[WEBDRIVER] [INFO] [fxdriver.Utils] Browser-specific offset (X,Y): 0, 79

[WEBDRIVER] [INFO] [fxdriver.Utils] Pending native events: false

[WEBDRIVER] [INFO] [fxdriver.Utils] Extra events processed: 0 Page Unloaded: 
false

[WEBDRIVER] [INFO] [fxdriver.Utils] Done main loop.

[WEBDRIVER] [INFO] [fxdriver.Utils] Done extra event loop, 8

"2014-11-12 14:20:06 [wsc Debug 
line:@https://172.30.12.109:7002/wscsample2/js/wscsample_call.js:116:7]"; 
wsc-common.js:2
"accept call" wsc-common.js:2
[WEBDRIVER] [INFO] [fxdriver.Utils] Done native event wait.

"2014-11-12 14:20:07 [wsc Debug 
line:wsc</c.addLocalStreams@https://172.30.12.109:7002/api/wsc-common.js:2:27758]"; 
wsc-common.js:2
"addLocalStream, peerConnectionNum: 1" wsc-common.js:2
"onMediaStreamEvent: LOCAL_STREAM_ADDED" wscsample_call.js:577
"Local audio stream is added..." wscsample_call.js:594
"Attaching media stream" wscsample_common_session.js:228
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</c.addLocalStreams@https://172.30.12.109:7002/api/wsc-common.js:2:27758]"; 
wsc-common.js:2
"call local media streams length : 1" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</c.setLocalDescription@https://172.30.12.109:7002/api/wsc-common.js:2:25159]";
 wsc-common.js:2
"Set local description now." wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</c.setLocalDescription@https://172.30.12.109:7002/api/wsc-common.js:2:25159]";
 wsc-common.js:2
"iceConnectionState/iceGatheringState is: new/complete" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug:]" wsc-common.js:2
"handleEndOfCandidate: got 'end of candidates' event, clear the timer." 
wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</c.sendAnswer@https://172.30.12.109:7002/api/wsc-call.js:2:17418]"; 
wsc-common.js:2
"Send message: {
     "control": {
         "type": "response",
         "package_type": "call",
         "session_id": "pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "subsession_id": 
"[email protected]",
         "sequence": 3,
         "message_state": "final",
         "correlation_id": "s1",
         "ack_sequence": 2,
         "version": "1.0"
     },
     "header": {
         "action": "start",
         "initiator": "[email protected]",
         "target": "[email protected]"
     },
     "payload": {
         "sdp": "v=0\r\no=Mozilla-SIPUA-32.0 23914 0 IN IP4 0.0.0.0\r\ns=SIP 
Call\r\nt=0 
0\r\na=ice-ufrag:40e99bb8\r\na=ice-pwd:2b2476aafd2dbacd7b6667c697bd37ea\r\na=fingerprint:sha-256 
DA:AF:7C:70:72:C8:2E:2D:56:78:D7:7B:D1:70:2B:5D:8C:4B:18:63:D1:5A:6B:71:89:C9:71:AB:2F:A2:A8:61\r\nm=audio
 49374 RTP/SAVPF 111 126\r\nc=IN IP4 172.30.12.239\r\na=rtpmap:111 
opus/48000/2\r\na=ptime:20\r\na=rtpmap:126 telephone-event/8000\r\na=fmtp:126 
0-15\r\na=sendrecv\r\na=setup:active\r\na=candidate:0 1 UDP 2128609535 192.168.1.3 49374 typ 
host\r\na=candidate:1 1 UDP 1692467199 172.30.12.239 49374 typ srflx raddr 192.168.1.3 rport 
49374\r\na=candidate:0 2 UDP 2128609534 192.168.1.3 49375 typ host\r\na=candidate:1 2 UDP 
1692467198 172.30.12.239 49375 typ srflx raddr 192.168.1.3 rport 49375\r\n"
     }
}" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</h.prototype.sendMessage@https://172.30.12.109:7002/api/wsc-common.js:3:4725]";
 wsc-common.js:2
"addMessage - cslw: 2,csuw: 3" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</c.initAnswerCtx/j/b@https://172.30.12.109:7002/api/wsc-call.js:2:19677]"; 
wsc-common.js:2
"Answer is sent...

v=0

o=Mozilla-SIPUA-32.0 23914 0 IN IP4 0.0.0.0

s=SIP Call

t=0 0

a=ice-ufrag:40e99bb8

a=ice-pwd:2b2476aafd2dbacd7b6667c697bd37ea

a=fingerprint:sha-256 
DA:AF:7C:70:72:C8:2E:2D:56:78:D7:7B:D1:70:2B:5D:8C:4B:18:63:D1:5A:6B:71:89:C9:71:AB:2F:A2:A8:61

m=audio 49374 RTP/SAVPF 111 126

c=IN IP4 172.30.12.239

a=rtpmap:111 opus/48000/2

a=ptime:20

a=rtpmap:126 telephone-event/8000

a=fmtp:126 0-15

a=sendrecv

a=setup:active

a=candidate:0 1 UDP 2128609535 192.168.1.3 49374 typ host

a=candidate:1 1 UDP 1692467199 172.30.12.239 49374 typ srflx raddr 192.168.1.3 
rport 49374

a=candidate:0 2 UDP 2128609534 192.168.1.3 49375 typ host

a=candidate:1 2 UDP 1692467198 172.30.12.239 49375 typ srflx raddr 192.168.1.3 
rport 49375

" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</c.sendAnswer@https://172.30.12.109:7002/api/wsc-call.js:2:17544]"; 
wsc-common.js:2
"Trying to update offer-answer state to : Answer sent" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Info]:" wsc-common.js:2
"Remote stream added." wsc-common.js:2
"onMediaStreamEvent: REMOTE_STREAM_ADDED" wscsample_call.js:577
"Remote audio stream is added..." wscsample_call.js:608
"Attaching media stream" wscsample_common_session.js:228
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</d.initWebSocket/a.wscWebsocket.onmessage@https://172.30.12.109:7002/api/wsc-common.js:3:11497]";
 wsc-common.js:2
"Received data from server: {
     "header": {
         "initiator": "[email protected]",
         "target": "[email protected]",
         "action": "complete"
     },
     "control": {
         "session_id": "pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "ack_sequence": 3,
         "package_type": "call",
         "sequence": 3,
         "subsession_id": 
"[email protected]",
         "type": "message",
         "correlation_id": "s2",
         "version": "1.0"
     }
}" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</d.handleWsData@https://172.30.12.109:7002/api/wsc-common.js:3:10130]"; 
wsc-common.js:2
"ackMessages - cslw: 4,csuw: 3" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</d.doMessage@https://172.30.12.109:7002/api/wsc-common.js:3:23994]"; 
wsc-common.js:2
"=== doCompleteMessage ===" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:g@https://172.30.12.109:7002/api/wsc-common.js:3:22817]"; wsc-common.js:2
"Trying to update offer-answer state to : Ack received" wsc-common.js:2
[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: setTimeout

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: findElement

[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementTagName

"2014-11-12 14:20:07 [wsc Debug 
line:wsc</d.initWebSocket/a.wscWebsocket.onmessage@https://172.30.12.109:7002/api/wsc-common.js:3:11497]";
 wsc-common.js:2
"Received data from server: {
     "payload": {
         "candidates": "a=mid:audio\r\na=candidate:3022624816 1 UDP 2122194687 
192.168.1.4 51058 typ host\r\na=candidate:3022624816 2 UDP 2122194687 192.168.1.4 51058 typ 
host\r\na=candidate:494278629 1 UDP 1685987071 172.30.12.240 51058 typ srflx raddr 192.168.1.4 
rport 51058\r\na=candidate:494278629 2 UDP 1685987071 172.30.12.240 51058 typ srflx raddr 
192.168.1.4 rport 51058\r\na=candidate:4205470912 1 TCP 1518214911 192.168.1.4 0 typ 
host\r\na=candidate:4205470912 2 TCP 1518214911 192.168.1.4 0 typ host\r\na=candidate:1 1 UDP 
16776959 172.30.12.136 22512 typ relay raddr 172.30.12.136 rport 22512\r\na=candidate:1 2 UDP 
16776958 172.30.12.136 22513 typ relay raddr 172.30.12.136 rport 
22513\r\na=end-of-candidates\r\n"
     },
     "header": {
         "initiator": "[email protected]",
         "target": "[email protected]",
         "action": "trickle"
     },
     "control": {
         "session_id": "pQAAAUmgZ4B/z28/ntJaERXGnLAAABEZ_76",
         "package_type": "call",
         "sequence": 4,
         "subsession_id": 
"[email protected]",
         "type": "message",
         "correlation_id": "s3",
         "version": "1.0"
     }
}" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:wsc</d.doMessage@https://172.30.12.109:7002/api/wsc-common.js:3:24187]"; 
wsc-common.js:2
"=== doTrickleIce ===" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:k/<@https://172.30.12.109:7002/api/wsc-common.js:3:23598]"; wsc-common.js:2
"addIceCandidate succeed, a=candidate:1 2 UDP 16776958 172.30.12.136 22513 typ relay 
raddr 172.30.12.136 rport 22513" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:k/<@https://172.30.12.109:7002/api/wsc-common.js:3:23598]"; wsc-common.js:2
"addIceCandidate succeed, a=candidate:1 2 UDP 16776958 172.30.12.136 22513 typ relay 
raddr 172.30.12.136 rport 22513" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:k/<@https://172.30.12.109:7002/api/wsc-common.js:3:23598]"; wsc-common.js:2
"addIceCandidate succeed, a=candidate:1 2 UDP 16776958 172.30.12.136 22513 typ relay 
raddr 172.30.12.136 rport 22513" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:k/<@https://172.30.12.109:7002/api/wsc-common.js:3:23598]"; wsc-common.js:2
"addIceCandidate succeed, a=candidate:1 2 UDP 16776958 172.30.12.136 22513 typ relay 
raddr 172.30.12.136 rport 22513" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:k/<@https://172.30.12.109:7002/api/wsc-common.js:3:23598]"; wsc-common.js:2
"addIceCandidate succeed, a=candidate:1 2 UDP 16776958 172.30.12.136 22513 typ relay 
raddr 172.30.12.136 rport 22513" wsc-common.js:2
[WEBDRIVER] [INFO] [fxdriver.nsCommandProcessor] Received command: 
getElementText

"2014-11-12 14:20:07 [wsc Debug 
line:k/<@https://172.30.12.109:7002/api/wsc-common.js:3:23598]"; wsc-common.js:2
"addIceCandidate succeed, a=candidate:1 2 UDP 16776958 172.30.12.136 22513 typ relay 
raddr 172.30.12.136 rport 22513" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:k/<@https://172.30.12.109:7002/api/wsc-common.js:3:23598]"; wsc-common.js:2
"addIceCandidate succeed, a=candidate:1 2 UDP 16776958 172.30.12.136 22513 typ relay 
raddr 172.30.12.136 rport 22513" wsc-common.js:2
"2014-11-12 14:20:07 [wsc Debug 
line:k/<@https://172.30.12.109:7002/api/wsc-common.js:3:23598]"; wsc-common.js:2
"addIceCandidate succeed, a=candidate:1 2 UDP 16776958 172.30.12.136 22513 typ relay 
raddr 172.30.12.136 rport 22513" wsc-common.js:2
ICE failed, see about:webrtc for more details


Hi Byron,
Here's what I have from about:webrtc. If it's not sufficient, I will have to 
setup this call flow in our lab again and collect more data, just let me know.

Thanks for taking a look,
Frank.



PeerConnection:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?) 14:20:26 GMT-0800 
(Pacific Standard Time)
ICE statistics
1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?): stream1/audio
Local candidate Remote candidate        ICE State       Priority        
Nominated       Selected
Local candidate addr    Type
192.168.1.3:49374/udp   host
172.30.12.239:49374/udp serverreflexive
192.168.1.3:49375/udp   host
172.30.12.239:49375/udp serverreflexive
Remote candidate addr   Type
Local SDP

v=0

o=Mozilla-SIPUA-32.0 23914 0 IN IP4 0.0.0.0

s=SIP Call

t=0 0

a=ice-ufrag:40e99bb8

a=ice-pwd:2b2476aafd2dbacd7b6667c697bd37ea

a=fingerprint:sha-256 
DA:AF:7C:70:72:C8:2E:2D:56:78:D7:7B:D1:70:2B:5D:8C:4B:18:63:D1:5A:6B:71:89:C9:71:AB:2F:A2:A8:61

m=audio 49374 RTP/SAVPF 111 126

c=IN IP4 172.30.12.239

a=rtpmap:111 opus/48000/2

a=ptime:20

a=rtpmap:126 telephone-event/8000

a=fmtp:126 0-15

a=sendrecv

a=setup:active

a=candidate:0 1 UDP 2128609535 192.168.1.3 49374 typ host

a=candidate:1 1 UDP 1692467199 172.30.12.239 49374 typ srflx raddr 192.168.1.3 
rport 49374

a=candidate:0 2 UDP 2128609534 192.168.1.3 49375 typ host

a=candidate:1 2 UDP 1692467198 172.30.12.239 49375 typ srflx raddr 192.168.1.3 
rport 49375

Remote SDP

v=0

o=- 4367238177690043858 2 IN IP4 127.0.0.1

s=Acme

t=0 0

m=audio 1 RTP/SAVPF 111 103 104 0 8 106 105 13 126

c=IN IP4 0.0.0.0

a=rtpmap:111 opus/48000/2

a=rtpmap:103 ISAC/16000

a=rtpmap:104 ISAC/32000

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:106 CN/32000

a=rtpmap:105 CN/16000

a=rtpmap:13 CN/8000

a=rtpmap:126 telephone-event/8000

a=fingerprint:sha-256 
EF:84:6D:55:1B:51:AB:D0:8C:38:28:B3:42:04:5E:A9:8E:33:4F:B3:DD:7D:D4:FA:A0:26:26:49:70:E3:CC:F3

a=setup:actpass

a=ice-ufrag:L4/sSx9NYyi7thsr

a=ice-pwd:htXLlfwB1Mkc1wBHokQAvWLi

a=rtcp:22513

a=sendrecv

RTP statistics
outbound_rtp_audio_0
Local: 14:20:26 GMT-0800 (Pacific Standard Time) outboundrtp SSRC: 1030498301 
Sent: 0 packets (0 Kb)
inbound_rtp_audio_1
Local: 14:20:26 GMT-0800 (Pacific Standard Time) inboundrtp SSRC: 0 Received: 0 
packets (0 Kb) Lost: 0 Jitter: 0
Logging:
(registry/INFO) insert 'ice' (registry) succeeded: ice
(registry/INFO) insert 'ice.pref' (registry) succeeded: ice.pref
(registry/INFO) insert 'ice.pref.type' (registry) succeeded: ice.pref.type
(registry/INFO) insert 'ice.pref.type.srv_rflx' (UCHAR) succeeded: 0x64
(registry/INFO) insert 'ice.pref.type.peer_rflx' (UCHAR) succeeded: 0x6e
(registry/INFO) insert 'ice.pref.type.host' (UCHAR) succeeded: 0x7e
(registry/INFO) insert 'ice.pref.type.relayed' (UCHAR) succeeded: 0x05
(registry/INFO) insert 'ice.pref.type.relayed_tcp' (UCHAR) succeeded: 0x00
(registry/INFO) insert 'ice.pref.interface' (registry) succeeded: 
ice.pref.interface
(registry/INFO) insert 'ice.pref.interface.rl0' (UCHAR) succeeded: 0xff
(registry/INFO) insert 'ice.pref.interface.wi0' (UCHAR) succeeded: 0xfe
(registry/INFO) insert 'ice.pref.interface.lo0' (UCHAR) succeeded: 0xfd
(registry/INFO) insert 'ice.pref.interface.en1' (UCHAR) succeeded: 0xfc
(registry/INFO) insert 'ice.pref.interface.en0' (UCHAR) succeeded: 0xfb
(registry/INFO) insert 'ice.pref.interface.eth0' (UCHAR) succeeded: 0xfc
(registry/INFO) insert 'ice.pref.interface.eth1' (UCHAR) succeeded: 0xfb
(registry/INFO) insert 'ice.pref.interface.eth2' (UCHAR) succeeded: 0xf9
(registry/INFO) insert 'ice.pref.interface.ppp' (UCHAR) succeeded: 0xfa
(registry/INFO) insert 'ice.pref.interface.ppp0' (UCHAR) succeeded: 0xf9
(registry/INFO) insert 'ice.pref.interface.en2' (UCHAR) succeeded: 0xf8
(registry/INFO) insert 'ice.pref.interface.en3' (UCHAR) succeeded: 0xf7
(registry/INFO) insert 'ice.pref.interface.em0' (UCHAR) succeeded: 0xfb
(registry/INFO) insert 'ice.pref.interface.em1' (UCHAR) succeeded: 0xfc
(registry/INFO) insert 'ice.pref.interface.vmnet0' (UCHAR) succeeded: 0xf0
(registry/INFO) insert 'ice.pref.interface.vmnet1' (UCHAR) succeeded: 0xf1
(registry/INFO) insert 'ice.pref.interface.vmnet3' (UCHAR) succeeded: 0xef
(registry/INFO) insert 'ice.pref.interface.vmnet4' (UCHAR) succeeded: 0xee
(registry/INFO) insert 'ice.pref.interface.vmnet5' (UCHAR) succeeded: 0xed
(registry/INFO) insert 'ice.pref.interface.vmnet6' (UCHAR) succeeded: 0xec
(registry/INFO) insert 'ice.pref.interface.vmnet7' (UCHAR) succeeded: 0xeb
(registry/INFO) insert 'ice.pref.interface.vmnet8' (UCHAR) succeeded: 0xea
(registry/INFO) insert 'ice.pref.interface.virbr0' (UCHAR) succeeded: 0xe9
(registry/INFO) insert 'ice.pref.interface.wlan0' (UCHAR) succeeded: 0xe8
(registry/INFO) insert 'stun' (registry) succeeded: stun
(registry/INFO) insert 'stun.client' (registry) succeeded: stun.client
(registry/INFO) insert 'stun.client.maximum_transmits' (UINT4) succeeded: 5
(registry/INFO) insert 'ice.trickle_grace_period' (UINT4) succeeded: 5000
(ice/WARNING) ICE(PC:1415830800292000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?)): No STUN servers 
specified
(ice/NOTICE) ICE(PC:1415830800292000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?)): No TURN servers 
specified
(generic/INFO) Found adapter with friendly name: Local Area Connection
(generic/INFO) Converted ifname: Local_Area_Connection
(generic/INFO) Adapter Local_Area_Connection address: 192.168.1.3
(registry/INFO) insert 'ice.pref.interface.Local_Area_Connection' (UCHAR) 
succeeded: 0xe0
(ice/WARNING) ICE(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?)): No STUN servers 
specified
(ice/NOTICE) ICE(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?)): No TURN servers 
specified
(stun/INFO) Found adapter with friendly name: Local Area Connection
(stun/INFO) Converted ifname: Local_Area_Connection
(stun/INFO) Adapter Local_Area_Connection address: 192.168.1.3
(ice/NOTICE) ICE(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?)): peer 
(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?):default) no 
streams with non-empty check lists
(ice/NOTICE) ICE(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?)): peer 
(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?):default) no 
streams with pre-answer requests
(ice/NOTICE) ICE(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?)): peer 
(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?):default) no checks 
to start
(ice/INFO) ICE(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?)): peer 
(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?):default) Trickle 
grace period is over; marking every component with only failed pairs as failed.
(ice/INFO) ICE-PEER(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?):default)/STREAM(1415830807388000
 (id=15 url=https://172.30.12.109:7002/wscsample2/sample_call.html?): 
stream1/audio)/COMP(1): All pairs are failed, and grace period has elapsed. 
Marking component as failed.
(ice/INFO) ICE-PEER(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?):default): all 
checks completed success=0 fail=1
(ice/INFO) ICE-PEER(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?):default)/STREAM(1415830807388000
 (id=15 url=https://172.30.12.109:7002/wscsample2/sample_call.html?): 
stream1/audio)/COMP(2): All pairs are failed, and grace period has elapsed. 
Marking component as failed.
(ice/INFO) ICE-PEER(PC:1415830807388000 (id=15 
url=https://172.30.12.109:7002/wscsample2/sample_call.html?):default): all 
checks completed success=0 fail=1

_______________________________________________
dev-media mailing list
[email protected]
https://lists.mozilla.org/listinfo/dev-media



_______________________________________________
dev-media mailing list
[email protected]
https://lists.mozilla.org/listinfo/dev-media

Re: chrome to firefox call fails when browsers behind different NAT devices and trickle ICE is used.

Reply via email to