Debugging ICE Connectivity from Chrome

2,894 views

Skip to first unread message

SteveG

unread,

Nov 27, 2013, 4:24:21 AM11/27/13

to discuss...@googlegroups.com

Hi,

I am testing out an ice-lite server implementation with Chrome. I see the originating chrome browser stay in ICEConnectionStateChecking (Chrome version:31.0.1650.57 m).

When I test against a server that supports full-ice the the iceConnectionState transitions nicely to the collected state and chrome_debug logs the sending and receipt of STUN.

How do I get as much debug info from the browser about the STUN exchange? I want to rule out bad formatting of the STUN message in the ice-lite scenario.

Currently I am collecting:

- pcaps (I see the STUN Binding Response received at the browser but Chrome continues to send Binding Request).

- chrome://webrtc-internals

I am running chrome with the following flags:

chrome.exe --enable-logging --v=4 --vmodule=*libjingle/source/talk/*=4 --vmodule=*media/audio/*=4

With those flags set should the chrome_debug.log report errors if the STUN packet it is receiving fails the FINGERPRINT or MESSAGE-INTEGRITY validation or is badly formatted in some manner?

The current logging (snippet below) in that file does not even hint that a STUN response has been received, I want to check I am set up to flag all of the debug data from chrome.

Cheers,

Steve

[7060:9552:1127/063818:INFO:CONSOLE(1)] "recv=SIP/2.0 200 OK

...

a=ice-lite

m=audio 1024 RTP/SAVPF 0 8

a=ice-ufrag:soundElV8GSUYsN

a=ice-pwd:sound1234567890abcdefg

a=candidate:1 1 UDP 2113955071 10.32.123.1 1024 typ host

[4360:7356:1127/063818:VERBOSE3:dtlstransportchannel.cc(225)] Jingle:Channel[audio|2|__]: Other side didn't support DTLS.

[4360:10536:1127/063818:VERBOSE3:session.cc(707)] No BUNDLE information, not bundling.

[4360:7356:1127/063818:VERBOSE3:channel.cc(923)] Channel enabled

[4360:7356:1127/063818:VERBOSE3:channel.cc(1714)] Changing voice state, recv=1 send=0

[4360:10536:1127/063818:VERBOSE3:session.cc(789)] Session:2241798014159433266 Old state:STATE_SENTINITIATE New state:STATE_RECEIVEDACCEPT Type:urn:xmpp:jingle:apps:rtp:1 Transport:http://www.google.com/transport/p2p

[4360:7356:1127/063818:VERBOSE3:channel.cc(1752)] Setting remote voice description

[4360:7356:1127/063818:VERBOSE3:srtpfilter.cc(397)] SRTP activated with negotiated parameters: send cipher_suite AES_CM_128_HMAC_SHA1_80 recv cipher_suite AES_CM_128_HMAC_SHA1_80

[4360:7356:1127/063818:VERBOSE3:channel.cc(1714)] Changing voice state, recv=1 send=0

[4360:7356:1127/063818:VERBOSE3:port.cc(843)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--W|-]: Connection created

[4360:7356:1127/063818:VERBOSE3:p2ptransportchannel.cc(702)] Jingle:Channel[audio|1|__]: Created connection with origin=2, (1 total)

[4360:7356:1127/063818:VERBOSE4:port.cc(1066)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--W|-]: UpdateState(): pings_since_last_response_=, rtt=3000, now=1261867463

[4360:7356:1127/063818:VERBOSE4:p2ptransportchannel.cc(899)] Sorting available connections:

[4360:7356:1127/063818:VERBOSE4:p2ptransportchannel.cc(901)] Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--W|-]

[4360:7356:1127/063818:VERBOSE3:p2ptransportchannel.cc(975)] Jingle:Channel[audio|1|__]: New best connection: Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--W|-]

[7060:9552:1127/063818:INFO:CONSOLE(1)] "SEND: ACK sip:40004...@10.32.123.249:5060 SIP/2.0

...

[7060:9552:1127/063818:INFO:CONSOLE(1)] "onSetRemoteDescriptionSuccess", source: http://sipml5.org/SIPml-api.js?svn=179 (1)

[7060:9552:1127/063818:INFO:CONSOLE(1)] "==session event = m_early_media", source: http://sipml5.org/SIPml-api.js?svn=179 (1)

[7060:9552:1127/063818:INFO:CONSOLE(1)] "==session event = connected", source: http://sipml5.org/SIPml-api.js?svn=179 (1)

[7060:9552:1127/063818:INFO:CONSOLE(1)] "==session event = m_stream_audio_remote_added", source: http://sipml5.org/SIPml-api.js?svn=179 (1)

...

[4360:7356:1127/063818:VERBOSE4:port.cc(1141)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--W|-]: Sending STUN ping Bt602Kewn9FN at 1261867482

[4360:7356:1127/063818:VERBOSE4:port.cc(1066)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--I|-]: UpdateState(): pings_since_last_response_=1261867482 , rtt=3000, now=1261867530

[4360:7356:1127/063818:VERBOSE4:port.cc(1141)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--I|-]: Sending STUN ping TtezgALFDuby at 1261867530

[4360:7356:1127/063818:VERBOSE4:port.cc(1141)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--I|-]: Sending STUN ping 0nYKCK3beXoP at 1261867578

[4360:7356:1127/063818:VERBOSE4:port.cc(1141)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--I|-]: Sending STUN ping s96jRwvk0S7c at 1261867626

[4360:7356:1127/063819:VERBOSE4:port.cc(1066)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--I|-]: UpdateState(): pings_since_last_response_=1261867482 1261867530 1261867578 1261867626 , rtt=3000, now=1261867674

[4360:7356:1127/063819:VERBOSE4:port.cc(1141)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--I|-]: Sending STUN ping ahUHx9lRXB2a at 1261867674

[4360:7356:1127/063819:VERBOSE4:port.cc(1141)] Jingle:Conn[audio:FNr2fJl4:1:0:local:udp:10.128.99.157:60197->:1:0:local:udp:10.32.123.1:1024|C--I|-]: Sending STUN ping bGSfXl/Q7rcE at 1261867722

SteveG

unread,

Dec 17, 2013, 5:50:18 AM12/17/13

to discuss...@googlegroups.com

Closing out my own question, this may help others. In my case I had miss calculated the message integrity I was sending in the STUN binding response (pay attention to rfc5389 15.4 with respect to the message length and integrity calc).

The debug below (and tracing through where chrome may silently discard the STUN response) were the only useful debug options I could find for following the ice procedure at the browser side.

- chrome://webrtc-internals

- chrome.exe --enable-logging --v=4 --vmodule=*libjingle/source/talk/*=4 --vmodule=*media/audio/*=4

- chrome_debug.log is here:

C:\$USERDATA\AppData\Local\Google\Chrome\User Data

I have further queries about the ICE procedures on chrome which I will post separately.

Reply all

Reply to author

Forward

0 new messages