datachannel relay issue

652 views
Skip to first unread message

WebRTCBud

unread,
Apr 24, 2017, 2:37:25 AM4/24/17
to discuss-webrtc
Hellow everyone,

Disclaimer: I am a newbie trying to learn WebRTC at the same time dissecting WebRTC logs to solve datachannel relay disconnection issues. My assumption is this lengthy list of questions and community/expert answers would help many newbies out there to launch themselves into the realm of WebRTC troubleshooting using logs. 

I took up a proof of concept application from a team, the application performs remote viewing using webrtc data channel. This proof of concept was developed from a WebRTC code base around Oct 2016.

The setup has simple-peer interface to webrtc library on one end and the other end uses chrome browser on a desktop. In our network setup, the simple peer side uses relay connection and webrtc data channel to deliver frame buffer vnc data over internet to the desktop. 

I am pretty new to this application and webrtc. I have started reading the STUN, TURN, ICE and SDP concepts using RFC's.

When I started running this application, I see that the peers get disconnected at random times. To understand the issue, I started analysing the webrtc logs on the simple-peer side. I have some observations, which I would like to get clarifications from the community here.


 I am pasting my log below for further discussion. I have annotations in blue. For easy discussion I have used color coding of green(I think are some success check points of my log), red(looks troubling to me) , blue text(my understanding and questions). Pls help me by pointing out wherever I am wrong.

If some one can advice me which part of the log looks troublesome and what tests I can perform to prove them it will be very helpful to solve my current issue. Also pls help me by giving some high level suggestions on how to attack connection drop issues in a deployment, I am ready to spend time and learn webrtc debugging.

(webrtcsdp.cc:2609): Ignored line: c=IN IP4 35.163.116.133
(webrtcsdp.cc:2738): Ignored line: a=sendrecv
(webrtcsdp.cc:2738): Ignored line: a=end-of-candidates
(webrtcsdp.cc:2738): Ignored line: a=sctpmap:5000 webrtc-datachannel 256
(webrtcsdp.cc:2738): Ignored line: a=ssrc:3994092364 cname:{1bc55660-b695-40ec-9fd1-8e552a8454a5}

(webrtcsdp.cc:1666): AddSctpDataCodec: Got SCTP Port Number 5000
(channel.cc:181): Created channel for sdparta_0
(channel.cc:313): Create non-RTCP TransportChannel for sdparta_0 on sdparta_0 transport 
(p2ptransportchannel.cc:396): Set ping most likely connection to 0
(p2ptransportchannel.cc:416): Set presume writable when fully relayed to 0
(transportcontroller.cc:498): Set remote transport description on sdparta_0
(p2ptransportchannel.cc:330): Remote supports ICE renomination ? 0

(webrtcsession.cc:820): Session:5109485956772807303 Old state:STATE_INIT New state:STATE_RECEIVEDOFFER

(channel.cc:2314): Setting remote data description
(channel.cc:2363): Changing data state, recv=0 send=0

(webrtcsession.cc:655): Local and Remote descriptions must be applied to get SSL Role of the session.
(webrtcsession.cc:655): Local and Remote descriptions must be applied to get SSL Role of the session.

Question - I have been wondering why am I getting the same log twice, can some one give some insight?

(webrtcsdp.cc:2609): Ignored line: c=IN IP4 0.0.0.0
(webrtcsdp.cc:2738): Ignored line: a=sctpmap:5000 webrtc-datachannel 1024

Quesiton - In my SDP I see that one end has 256 as last parameter and the other end has 1024, should I be concerned?

(webrtcsdp.cc:1666): AddSctpDataCodec: Got SCTP Port Number 5000
(transportcontroller.cc:478): Set local transport description on sdparta_0
(p2ptransportchannel.cc:319): Set ICE ufrag: GBWp1 pwd: 1+vMXcZdKKJipc3FQ65RNCnn on transport sdparta_0
(dtlstransportchannel.cc:326): Jingle:Channel[sdparta_0|1|__]: DTLS setup complete.
(channel.cc:880): Channel enabled
(channel.cc:2363): Changing data state, recv=0 send=0
(webrtcsession.cc:820): Session:5109485956772807303 Old state:STATE_RECEIVEDOFFER New state:STATE_INPROGRESS
(channel.cc:2239): Setting local data description
(channel.cc:2363): Changing data state, recv=1 send=0
(webrtcsession.cc:1353): Changing IceConnectionState 0 => 1

(basicportallocator.cc:272): Start getting ports with prune_turn_ports disabled
(basicportallocator.cc:661): Network manager has started
(basicportallocator.cc:586): Allocate ports on 1 networks


(basicportallocator.cc:1128): Jingle:Net[eth0:192.168.0.0/24:Unknown]: Allocation Phase=Udp
(port.cc:203): Jingle:Port[0x707ff768::1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Port created with network cost 50

(basicportallocator.cc:1219): AllocationSequence: UDPPort will be handling the STUN candidate generation.
(basicportallocator.cc:683): Adding allocated port for sdparta_0
(basicportallocator.cc:703): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Added port to allocator
(basicportallocator.cc:720): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Gathered candidate: Cand[:3659473419:1:udp:2122260223:192.168.]
(basicportallocator.cc:747): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Port ready.

Question - do I get port ready as soon as the first candidate is gathered?

(physicalsocketserver.cc:593): Socket::OPT_DSCP not supported.


(p2ptransportchannel.cc:518): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: SetOption(5, 0) failed: 0

(port.cc:877): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--W|0|0|91150052702823541d

Question - I am not able to locate in code from where this gets printed, can some one pls point me to the location? I have my own interpretation that its a connection between local candidate to remote candidate, but I am unbale to understand the bits such as C--W, some times its C--I, etc.,

(p2ptransportchannel.cc:873): Jingle:Channel[sdparta_0|1|__]: Created connection with origin=2, (1 total)
(port.cc:877): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--W|0|0|9114723795305643518|d
(p2ptransportchannel.cc:873): Jingle:Channel[sdparta_0|1|__]: Created connection with origin=2, (2 total)
(port.cc:877): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--W|0|0|72415419101566888d
(p2ptransportchannel.cc:873): Jingle:Channel[sdparta_0|1|__]: Created connection with origin=2, (3 total)
(port.cc:877): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--W|0|0|72412604351799782d
(p2ptransportchannel.cc:873): Jingle:Channel[sdparta_0|1|__]: Created connection with origin=2, (4 total)
(port.cc:877): Jingle:Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|C--W|0|0|396069377041907198d
(p2ptransportchannel.cc:873): Jingle:Channel[sdparta_0|1|__]: Created connection with origin=2, (5 total)
(port.cc:877): Jingle:Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb:1:92151551:relay:udp:35.163.116.133:56517|C--W|0|0|395787902065196542d
(p2ptransportchannel.cc:873): Jingle:Channel[sdparta_0|1|__]: Created connection with origin=2, (6 total)


(p2ptransportchannel.cc:1410): Jingle:Channel[sdparta_0|1|__]: Transport channel state changed from 0 to 1
(transportcontroller.cc:639): sdparta_0 TransportChannel 1 state changed. Check if state is complete.

(p2ptransportchannel.cc:1073): Jingle:Channel[sdparta_0|1|__]: Have a pingable connection for the first time; starting to ping.

(basicportallocator.cc:763): Not yet signaling candidate because protocol is not yet enabled.
(stunport.cc:373): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Starting STUN host lookup for stun.l.google.com:19302
(basicportallocator.cc:879): Signaling candidate because protocol was enabled: Cand[:3659473419:1:udp:2122260223:192.168.0.14:56101:local::0:GBWp:1+vMXcZdKKJipc3FQ65RNCn]

Question - Not yet signalling to signalling is this a race condition? Or its pretty normal and can be ignored? 

(messagequeue.cc:537): Message took 338ms to dispatch. Posted from: Start@../../webrtc/p2p/client/basicportallocator.cc:1108
(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--W|0|0|91150052702823540

(bitrate_prober.cc:49): Bandwidth probing enabled, set to inactive
(remote_bitrate_estimator_single_stream.cc:61): RemoteBitrateEstimatorSingleStream: Instantiating.
(bitrate_prober.cc:78): Probe cluster (bitrate:probes): (900000:6) 
(bitrate_prober.cc:78): Probe cluster (bitrate:probes): (1800000:5) 
(probe_controller.cc:95): Measured bitrate: 300000 Minimum to probe further: 1200000
(congestion_controller.cc:359): Bitrate estimate state changed, BWE: 300000 bps.
(bitrate_allocator.cc:79): Current BWE 300000

(thread.cc:278): Waiting for the thread to join, but blocking calls have been disallowed

Question - Can some one pls tell me what is this log about? I see this in all the logs I get for all my tests.

(basicportallocator.cc:1128): Jingle:Net[eth0:192.168.0.0/24:Unknown]: Allocation Phase=Relay
(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--W|0|0|91147237953056435180
(basicportallocator.cc:720): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Gathered candidate: Cand[:739204063:1:udp:1686052607:182.74.11]
(basicportallocator.cc:829): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Port completed gathering candidates.

Question - how does the port know that it has gathered all the candidates? 
I don't get this log in UDP allocation phase, what is the reason?

(port.cc:1411): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--W|0|0|72415419101566880


(basicportallocator.cc:1128): Jingle:Net[eth0:192.168.0.0/24:Unknown]: Allocation Phase=Tcp
(port.cc:203): Jingle:Port[0x6f11b3f0::1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Port created with network cost 50
(basicportallocator.cc:683): Adding allocated port for sdparta_0
(basicportallocator.cc:703): Jingle:Port[0x6f11b3f0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Added port to allocator
(basicportallocator.cc:720): Jingle:Port[0x6f11b3f0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Gathered candidate: Cand[:2493308667:1:tcp:1518280447:192.168.]
(basicportallocator.cc:747): Jingle:Port[0x6f11b3f0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Port ready.
(physicalsocketserver.cc:593): Socket::OPT_DSCP not supported.
(p2ptransportchannel.cc:518): Jingle:Port[0x6f11b3f0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: SetOption(5, 0) failed: 0

(basicportallocator.cc:763): Not yet signaling candidate because protocol is not yet enabled.
(basicportallocator.cc:829): Jingle:Port[0x6f11b3f0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Port completed gathering candidates.
(basicportallocator.cc:879): Signaling candidate because protocol was enabled: Cand[:2493308667:1:tcp:1518280447:192.168.0.14:34146:local::0:GBWp:1+vMXcZdKKJipc3FQ65RNCn]
(port.cc:1411): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--W|0|0|72412604351799780

(basicportallocator.cc:1128): Jingle:Net[eth0:192.168.0.0/24:Unknown]: Allocation Phase=SslTcp

(basicportallocator.cc:953): All candidates gathered for sdparta_0:1:0
(p2ptransportchannel.cc:572): P2PTransportChannel: sdparta_0, component 1 gathering complete
 
Question - Can some one tell me the rationale for these two logs? Is it like, during 4 allocations phases, udp, tcp, relay, ssltcp we try to get host, srflx, relay, candidates and state we are done? 

I always see under SslTcp phase no candidate is gathered, any idea why?

(port.cc:1411): Jingle:Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|C--W|0|0|396069377041907190
(port.cc:1411): Jingle:Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb:1:92151551:relay:udp:35.163.116.133:56517|C--W|0|0|395787902065196540
(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540
(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180
(port.cc:1411): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--I|0|0|72415419101566880
(port.cc:1411): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--I|0|0|72412604351799780
(port.cc:1411): Jingle:Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|C--I|0|0|396069377041907190

(alr_detector.cc:57): ALR start

(port.cc:1411): Jingle:Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb:1:92151551:relay:udp:35.163.116.133:56517|C--I|0|0|395787902065196540
(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540
(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180
(port.cc:1411): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--I|0|0|72415419101566880
(port.cc:1003): Jingle:Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|C--I|0|0|396069377041907195
(port.cc:607): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=35.163.116.133:64257, id=73eb3b9ae28ba3e5595a70b5
(p2ptransportchannel.cc:735): Not switching the selected connection on controlled side yet: Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox]
(port.cc:1003): Jingle:Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb:1:92151551:relay:udp:35.163.116.133:56517|C--I|0|0|39578790206519654a
(port.cc:607): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=35.163.116.133:56517, id=34873cc560e07266713a2e9a
(p2ptransportchannel.cc:735): Not switching the selected connection on controlled side yet: Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb]
(p2ptransportchannel.cc:1971): Selecting connection for triggered check: Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:u]
(port.cc:1411): Jingle:Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CR-I|1|0|396069377041907190
(port.cc:1003): Jingle:Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CR-I|1|0|39606937704190719d
(port.cc:607): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=35.163.116.133:64257, id=0bed46b96fb22986bdd6e8bd
(port.cc:1358): Jingle:Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CR-I|1|0|39606937704190719 
(port.cc:1495): Jingle:Conn[0x6f1115f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CRWS|1|0|39606937704190719.
(p2ptransportchannel.cc:238): Switching selected connection due to sorting

(p2ptransportchannel.cc:1381): Jingle:Channel[sdparta_0|1|R_]: New selected connection: Conn[0x6f1115f8:sdparta_0:FmhKR6b1:1:0:stun:udp:182.74.112.50:56101->3sDue8ox:1:]

(port.cc:1115): Jingle:Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb:1:92151551:relay:udp:35.163.116.133:56517|CR-I|1|0|39578790206519654d
(opensslstreamadapter.cc:790): BeginSSL with peer.
(openssladapter.cc:851): SSL_connect:before/connect initialization
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:861): SSL_connect:error in unknown state

(dtlstransportchannel.cc:641): Jingle:Channel[sdparta_0|1|__]: DtlsTransportChannelWrapper: Started DTLS handshake

(port.cc:1411): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--I|0|0|72412604351799780
(port.cc:1003): Jingle:Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb:1:92151551:relay:udp:35.163.116.133:56517|CRxI|1|0|395787902065196546
(port.cc:607): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=35.163.116.133:56517, id=ab8d66d709723775465dd126
(port.cc:1003): Jingle:Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb:1:92151551:relay:udp:35.163.116.133:56517|CRxI|1|0|395787902065196546
(port.cc:607): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=35.163.116.133:56517, id=ab8d66d709723775465dd126
(port.cc:1003): Jingle:Conn[0x6f1121f8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->zczsdglb:1:92151551:relay:udp:35.163.116.133:56517|CRxI|1|0|395787902065196546
(port.cc:607): Jingle:Port[0x707ff768:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=35.163.116.133:56517, id=ab8d66d709723775465dd126

(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540

(openssladapter.cc:851): SSL_connect:unknown state

(opensslstreamadapter.cc:1130): Accepted peer certificate.
(opensslstreamadapter.cc:1130): Accepted peer certificate.

(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:851): SSL_connect:unknown state
(openssladapter.cc:861): SSL_connect:error in unknown state
(openssladapter.cc:861): SSL_connect:error in unknown state
(openssladapter.cc:861): SSL_connect:error in unknown state
(openssladapter.cc:861): SSL_connect:error in unknown state
(openssladapter.cc:861): SSL_connect:error in unknown state
(openssladapter.cc:851): SSL_connect:unknown state

(dtlstransportchannel.cc:587): Jingle:Channel[sdparta_0|1|__]: DTLS handshake complete.
(transportcontroller.cc:571):  TransportChannel sdparta_0 1 writability changed to 1.
(channel.cc:910): Channel writable (sdparta_0) for the first time
(channel.cc:914): Using Cand[:739204063:1:udp:1686052607::56101:stun:192.168.0.14:56101:GBWp:1+vMXcZdKKJipc3FQ65RNCnn:1:50:0]->Cand[:3:1:udp:92217087:35.16]

(sctpdataengine.cc:251): InitializeUsrSctp
(webrtcsession.cc:1385): Changing to ICE connected state because all transports are writable.
(webrtcsession.cc:1353): Changing IceConnectionState 1 => 2
(channel.cc:2363): Changing data state, recv=1 send=1

(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180

(datachannel.cc:636): Sent CONTROL message on channel 1

Question --Can some one pls tell me what this control message is about on channel 1?

(port.cc:1411): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--I|0|0|72415419101566880
(port.cc:1411): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--I|0|0|72412604351799780

(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540

(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180

(port.cc:1411): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--I|0|0|72415419101566880
(port.cc:1411): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--I|0|0|72412604351799780


(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540


(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

(port.cc:1411): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--I|0|0|72415419101566880
(port.cc:1411): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--I|0|0|72412604351799780

(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540

(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

My observation - I see this error even in a successful relay connection data transfer which does not disconnect very randomly.

(port.cc:1411): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--I|0|0|72415419101566880
(port.cc:1411): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--I|0|0|72412604351799780

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540
(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

(port.cc:1411): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--I|0|0|72415419101566880
(port.cc:1411): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--I|0|0|72412604351799780

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

(port.cc:1411): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540
(port.cc:1411): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180
(port.cc:1203): Jingle:Conn[0x6f110020:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->pqCWUMVu:1:2122252543:local:udp:192.168.0.112:57381|C--I|0|0|91150052702823540
(port.cc:1203): Jingle:Conn[0x6f110a50:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->/OZkesag:1:2122187007:local:udp:172.17.0.1:43489|C--I|0|0|91147237953056435180
(port.cc:1203): Jingle:Conn[0x6f110db8:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->3b74jToT:1:1686052863:stun:udp:115.160.228.10:57381|C--I|0|0|72415419101566880
(port.cc:1203): Jingle:Conn[0x6f111290:sdparta_0:wVVyh9oP:1:0:local:udp:192.168.0.14:56101->H0zyjdv9:1:1685987327:stun:udp:115.160.228.10:43489|C--I|0|0|72412604351799780

(p2ptransportchannel.cc:1410): Jingle:Channel[sdparta_0|1|RW]: Transport channel state changed from 1 to 2
(transportcontroller.cc:639): sdparta_0 TransportChannel 1 state changed. Check if state is complete.

(port.cc:1457): Connection deleted with number of pings sent: 9
(p2ptransportchannel.cc:1820): Jingle:Channel[sdparta_0|1|RW]: Removed connection 0x6f110020 (5 remaining)
(port.cc:1457): Connection deleted with number of pings sent: 9
(p2ptransportchannel.cc:1820): Jingle:Channel[sdparta_0|1|RW]: Removed connection 0x6f110a50 (4 remaining)
(port.cc:1457): Connection deleted with number of pings sent: 8
(p2ptransportchannel.cc:1820): Jingle:Channel[sdparta_0|1|RW]: Removed connection 0x6f110db8 (3 remaining)
(port.cc:1457): Connection deleted with number of pings sent: 8
(p2ptransportchannel.cc:1820): Jingle:Channel[sdparta_0|1|RW]: Removed connection 0x6f111290 (2 remaining)

Question - Are the following errors catastrophic?

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

(port.cc:1457): Connection deleted with number of pings sent: 2
(p2ptransportchannel.cc:1820): Jingle:Channel[sdparta_0|1|RW]: Removed connection 0x6f1121f8 (1 remaining)

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

(port.cc:1403): Jingle:Conn[0x6f1115f8:sdparta_0:FmhKR6b1:1:0:stun:udp:182.74.112.50:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CRWS|1|0|3960693761694919s

Seems to be the only remaining connection, is this because its receiving ping responses. Pls correct me if I am wrong.

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

...many more similar logs as above....runs for pages
(port.cc:1403): Jingle:Conn[0x6f1115f8:sdparta_0:FmhKR6b1:1:0:stun:udp:182.74.112.50:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CRWS|1|0|3960693761694919s

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

...many more similar logs as above...runs for pages...

(port.cc:1403): Jingle:Conn[0x6f1115f8:sdparta_0:FmhKR6b1:1:0:stun:udp:182.74.112.50:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CRWS|1|0|3960693761694919s
(port.cc:1403): Jingle:Conn[0x6f1115f8:sdparta_0:FmhKR6b1:1:0:stun:udp:182.74.112.50:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CRWI|1|0|3960693761694919s
(port.cc:1187): Jingle:Conn[0x6f1115f8:sdparta_0:FmhKR6b1:1:0:stun:udp:182.74.112.50:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CRWI|1|0|39606937616949190
(port.cc:1411): Jingle:Conn[0x6f1115f8:sdparta_0:FmhKR6b1:1:0:stun:udp:182.74.112.50:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CRwI|1|0|39606937616949190

If my understanding is right, looks like there is still a connection but we can no more write to it.

(transportcontroller.cc:571):  TransportChannel sdparta_0 1 writability changed to 0.
(channel.cc:1073): Channel not writable (sdparta_0)
(channel.cc:2363): Changing data state, recv=1 send=1
(webrtcsession.cc:1353): Changing IceConnectionState 2 => 5
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(webrtcsession.cc:820): Session:5109485956772807303 Old state:STATE_INPROGRESS New state:STATE_CLOSED
(channel.cc:890): Channel disabled
(sctpdataengine.cc:293): UninitializeUsrSctp

Question -Is my channel closed because of lots of "(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned"?

(channel.cc:2363): Changing data state, recv=0 send=0
(opensslstreamadapter.cc:923): Cleanup
(openssladapter.cc:854): SSL3 alert write:warning:close notify
(channel.cc:200): Destroyed channel
------------------------

Any specific to general inputs will be highly appreciated on this issue. I have been browsing code, reading and testing to solve this issue night and day for the last 3 weeks unable to get confident on my own clues. Please help!!

Taylor Brandstetter

unread,
Apr 24, 2017, 4:10:00 PM4/24/17
to discuss-webrtc
Tried to respond to all questions:
 
Question - I have been wondering why am I getting the same log twice, can some one give some insight?

Nothing meaningful in this case. Just some code that ends up being executed twice. 

Quesiton - In my SDP I see that one end has 256 as last parameter and the other end has 1024, should I be concerned?

Not unless you need more than 256 channels. 

Question - do I get port ready as soon as the first candidate is gathered?

Yes; as soon as a port gathers a "pairable" candidate. 

Question - I am not able to locate in code from where this gets printed, can some one pls point me to the location? I have my own interpretation that its a connection between local candidate to remote candidate, but I am unbale to understand the bits such as C--W, some times its C--I, etc.,


Question - Not yet signalling to signalling is this a race condition? Or its pretty normal and can be ignored? 

Normal and can be ignored. 

(thread.cc:278): Waiting for the thread to join, but blocking calls have been disallowed

Question - Can some one pls tell me what is this log about? I see this in all the logs I get for all my tests.

I've seen this too; I'm not sure what causes it.
 
Question - how does the port know that it has gathered all the candidates? 

If there are STUN servers provided, the "UDP port" is done gathering after it receives a binding response from each server (or the request timed out).

I don't get this log in UDP allocation phase, what is the reason?

Just timing, since it take a round trip to receive the STUN response. 
 
(basicportallocator.cc:953): All candidates gathered for sdparta_0:1:0
(p2ptransportchannel.cc:572): P2PTransportChannel: sdparta_0, component 1 gathering complete
 
Question - Can some one tell me the rationale for these two logs? Is it like, during 4 allocations phases, udp, tcp, relay, ssltcp we try to get host, srflx, relay, candidates and state we are done? 

Basically. Though this concept of "phases" is just old code we haven't cleaned up.
 
I always see under SslTcp phase no candidate is gathered, any idea why?

We don't create SSL server sockets; we just make outgoing SSL connections if a remote "ssltcp" candidate is passed in. So again, probably just some code that needs cleaning up.
 
(datachannel.cc:636): Sent CONTROL message on channel 1

Question --Can some one pls tell me what this control message is about on channel 1?

This is for the WebRTC data channel "open/ack" handshake that occurs in-band.
 
Question - Are the following errors catastrophic?

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

They shouldn't be. If it's logged at "error" level right now we should probably reduce the level.
 
(port.cc:1403): Jingle:Conn[0x6f1115f8:sdparta_0:FmhKR6b1:1:0:stun:udp:182.74.112.50:56101->3sDue8ox:1:92217087:relay:udp:35.163.116.133:64257|CRWS|1|0|3960693761694919s

Seems to be the only remaining connection, is this because its receiving ping responses. Pls correct me if I am wrong.

Yes; if it's the only connection left, that means it's the highest-priority connection for which connectivity checks succeeded.
 
If my understanding is right, looks like there is still a connection but we can no more write to it.

(transportcontroller.cc:571):  TransportChannel sdparta_0 1 writability changed to 0.
(channel.cc:1073): Channel not writable (sdparta_0)

Correct. This log probably means ICE connectivity checks are failing.
 
(channel.cc:2363): Changing data state, recv=1 send=1
(webrtcsession.cc:1353): Changing IceConnectionState 2 => 5
(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned
(webrtcsession.cc:820): Session:5109485956772807303 Old state:STATE_INPROGRESS New state:STATE_CLOSED
(channel.cc:890): Channel disabled
(sctpdataengine.cc:293): UninitializeUsrSctp

Question -Is my channel closed because of lots of "(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned"?

The only thing that could cause "New state:STATE_CLOSED" is if you called "close" on the PeerConnection. That will close any attached data channels.

Do you have code that closes the PeerConnection when the ICE state changes to "disconnected" (which is recoverable)? If so, what happens if you don't do this; does it recover?

Nils Ohlmeier

unread,
Apr 24, 2017, 7:46:13 PM4/24/17
to discuss...@googlegroups.com
On Apr 21, 2017, at 10:17, WebRTCBud <nsc...@gmail.com> wrote:
Disclaimer: I am a newbie trying to learn WebRTC at the same time dissecting WebRTC logs to solve datachannel relay disconnection issues. My assumption is this lengthy list of questions and community/expert answers would help many newbies out there to launch themselves into the realm of WebRTC troubleshooting using logs. 

I took up a proof of concept application from a team, the application performs remote viewing using webrtc data channel. This proof of concept was developed from a WebRTC code base around Oct 2016.

The setup has simple-peer interface to webrtc library on one end and the other end uses chrome browser on a desktop. In our network setup, the simple peer side uses relay connection and webrtc data channel to deliver frame buffer vnc data over internet to the desktop. 

I am pretty new to this application and webrtc. I have started reading the STUN, TURN, ICE and SDP concepts using RFC's.

When I started running this application, I see that the peers get disconnected at random times. To understand the issue, I started analysing the webrtc logs on the simple-peer side. I have some observations, which I would like to get clarifications from the community here.

As your log appears to be from a connection between Chrome and Firefox: do you know if your connection problem only comes up between the two different browser?
Or does the problem also exist for Chrome to Chrome and/or Firefox to Firefox connections?

signature.asc

WebRTCBud

unread,
Apr 26, 2017, 1:41:11 PM4/26/17
to discuss-webrtc

Hi Taylor,


Thank you very much for your valuable time in replying to all my questions. It gave me good insight into what is going on. As you suggested, I have commented the code in my app that was closing PeerConnection on disconnected event. After this change I am seeing new logs as mentioned below.


Should I consider logs like “adding resurrected candidate”, “selecting connection for triggered check” as ICE recovery steps? The following is the log with some parts removed for beverity. I have higlighted few places which I see as key things, please give me your comments.


Can you pls give me some hints on what is going on and how do I debug this issue?


Log:

------

--Removed other logs for clarity--

......

......

(transportcontroller.cc:571): TransportChannel sdparta_0 1 writability changed to 0.

(channel.cc:1073): Channel not writable (sdparta_0)

(messagequeue.cc:537): Message took 105ms to dispatch. Posted from: RequestSortAndStateUpdate@../../webrtc/p2p/base/p2ptransportchannel.cc:1059

(channel.cc:2363): Changing data state, recv=1 send=1


Q – how to figure out what went wrong? Are there any commands I can use?


(messagequeue.cc:537): Message took 59ms to dispatch. Posted from: UpdateMediaSendRecvState@../../webrtc/pc/channel.cc:1666

(port.cc:1411): Jingle:Conn[0x2cf6090:sdparta_0:4+bjnZjB:1:0:stun:udp:182.74.20.50:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510


(webrtcsession.cc:1353): Changing IceConnectionState 2 => 5



(messagequeue.cc:537): Message took 242ms to dispatch. Posted from: UpdateAggregateStates_n@../../webrtc/p2p/base/transportcontroller.cc:682

(sctpdataengine.cc:670): SctpDataMediaChannel->SendData(...): EWOULDBLOCK returned

(messagequeue.cc:537): Message took 489ms to dispatch. Posted from: OnDataChannelReadyToSend@../../webrtc/pc/channel.cc:2447

(messagequeue.cc:537): Message took 238ms to dispatch. Posted from: RequestSortAndStateUpdate@../../webrtc/p2p/base/p2ptransportchannel.cc:1059

(messagequeue.cc:537): Message took 64ms to dispatch. Posted from: UpdateAggregateStates_n@../../webrtc/p2p/base/transportcontroller.cc:688

(messagequeue.cc:537): Message took 474ms to dispatch. Posted from: HandlePacket@../../webrtc/pc/channel.cc:829

(messagequeue.cc:537): Message took 61ms to dispatch. Posted from: OnMessage@../../webrtc/p2p/base/stunrequest.cc:223

(port.cc:1411): Jingle:Conn[0x2cf6090:sdparta_0:4+bjnZjB:1:0:stun:udp:182.74.20.50:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 947ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 747ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 171ms to dispatch. Posted from: OnSctpOutboundPacket@../../webrtc/media/sctp/sctpdataengine.cc:205

(messagequeue.cc:537): Message took 174ms to dispatch. Posted from: SignalSentPacket_n@../../webrtc/pc/channel.cc:1458

(messagequeue.cc:537): Message took 87ms to dispatch. Posted from: OnMessage@../../webrtc/p2p/base/stunrequest.cc:223

(port.cc:1411): Jingle:Conn[0x2cf6090:sdparta_0:4+bjnZjB:1:0:stun:udp:182.74.20.50:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 1460ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 153ms to dispatch. Posted from: SignalSentPacket_n@../../webrtc/pc/channel.cc:1458

(port.cc:1203): Jingle:Conn[0x2cf6090:sdparta_0:4+bjnZjB:1:0:stun:udp:182.74.20.50:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510



(p2ptransportchannel.cc:1410): Jingle:Channel[sdparta_0|1|R_]: Transport channel state changed from 2 to 3

(transportcontroller.cc:639): sdparta_0 TransportChannel 1 state changed. Check if state is complete.

(messagequeue.cc:537): Message took 137ms to dispatch. Posted from: RequestSortAndStateUpdate@../../webrtc/p2p/base/p2ptransportchannel.cc:1059



(webrtcsession.cc:1353): Changing IceConnectionState 5 => 4



(messagequeue.cc:537): Message took 126ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 185ms to dispatch. Posted from: UpdateAggregateStates_n@../../webrtc/p2p/base/transportcontroller.cc:682

(port.cc:1411): Jingle:Conn[0x2cf6090:sdparta_0:4+bjnZjB:1:0:stun:udp:182.74.20.50:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 1399ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544







(messagequeue.cc:537): Message took 103ms to dispatch. Posted from: OnMessage@../../webrtc/p2p/base/stunrequest.cc:223

(port.cc:1457): Connection deleted with number of pings sent: 5854

(p2ptransportchannel.cc:1820): Jingle:Channel[sdparta_0|1|__]: Removed connection 0x2cf6090 (0 remaining)

(p2ptransportchannel.cc:1831): Selected connection destroyed. Will choose a new one.

(p2ptransportchannel.cc:1394): Jingle:Channel[sdparta_0|1|__]: No selected connection

(messagequeue.cc:537): Message took 52ms to dispatch. Posted from: Destroy@../../webrtc/p2p/base/port.cc:1124

(port.cc:307): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received non-STUN packet from unknown address (54.)

(port.cc:307): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received non-STUN packet from unknown address (54.)

(port.cc:307): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received non-STUN packet from unknown address (54.)

(port.cc:307): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received non-STUN packet from unknown address (54.)

(port.cc:312): Received STUN ping id=04386ef8ed319c309e638de0 from unknown address 54.202.150.65:53351

(port.cc:877): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:53351|d




(p2ptransportchannel.cc:689): Adding connection from resurrected candidate: Cand[:3:1:udp:92217087:54.202.150.65:53351:relay:54.202.150.65:5]




(port.cc:607): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=54.202.150.65:53351, 0

(p2ptransportchannel.cc:1410): Jingle:Channel[sdparta_0|1|__]: Transport channel state changed from 3 to 2

(transportcontroller.cc:639): sdparta_0 TransportChannel 1 state changed. Check if state is complete.




(p2ptransportchannel.cc:1971): Selecting connection for triggered check: Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->]





(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 51ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 197ms to dispatch. Posted from: HandlePacket@../../webrtc/pc/channel.cc:829

(messagequeue.cc:537): Message took 206ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 379ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 112ms to dispatch. Posted from: OnSctpOutboundPacket@../../webrtc/media/sctp/sctpdataengine.cc:205

(messagequeue.cc:537): Message took 84ms to dispatch. Posted from: SignalSentPacket_n@../../webrtc/pc/channel.cc:1458

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(port.cc:1003): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533517

(port.cc:607): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=54.202.150.65:53351, 7



(messagequeue.cc:537): Message took 557ms to dispatch. Posted from: HandlePacket@../../webrtc/pc/channel.cc:829

(p2ptransportchannel.cc:1971): Selecting connection for triggered check: Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->]




(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 839ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 259ms to dispatch. Posted from: SignalSentPacket_n@../../webrtc/pc/channel.cc:1458

(messagequeue.cc:537): Message took 86ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 298ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 53ms to dispatch. Posted from: RequestSortAndStateUpdate@../../webrtc/p2p/base/p2ptransportchannel.cc:1059

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 63ms to dispatch. Posted from: UpdateAggregateStates_n@../../webrtc/p2p/base/transportcontroller.cc:688

(messagequeue.cc:537): Message took 109ms to dispatch. Posted from: UpdateAggregateStates_n@../../webrtc/p2p/base/transportcontroller.cc:688

(messagequeue.cc:537): Message took 227ms to dispatch. Posted from: RequestSortAndStateUpdate@../../webrtc/p2p/base/p2ptransportchannel.cc:1059

(messagequeue.cc:537): Message took 342ms to dispatch. Posted from: HandlePacket@../../webrtc/pc/channel.cc:829

(messagequeue.cc:537): Message took 68ms to dispatch. Posted from: OnSctpOutboundPacket@../../webrtc/media/sctp/sctpdataengine.cc:205

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 871ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 266ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 87ms to dispatch. Posted from: UpdateAggregateStates_n@../../webrtc/p2p/base/transportcontroller.cc:688

(messagequeue.cc:537): Message took 399ms to dispatch. Posted from: HandlePacket@../../webrtc/pc/channel.cc:829

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 2813ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 111ms to dispatch. Posted from: SignalSentPacket_n@../../webrtc/pc/channel.cc:1458

(messagequeue.cc:537): Message took 78ms to dispatch. Posted from: OnSctpOutboundPacket@../../webrtc/media/sctp/sctpdataengine.cc:205

(messagequeue.cc:537): Message took 229ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 98ms to dispatch. Posted from: ice_gathering_state@../../webrtc/api/peerconnectionproxy.h:76

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 980ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 52ms to dispatch. Posted from: RequestSortAndStateUpdate@../../webrtc/p2p/base/p2ptransportchannel.cc:1059

(messagequeue.cc:537): Message took 129ms to dispatch. Posted from: SignalSentPacket_n@../../webrtc/pc/channel.cc:1458

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(messagequeue.cc:537): Message took 87ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 133ms to dispatch. Posted from: HandlePacket@../../webrtc/pc/channel.cc:829

(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(port.cc:1003): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533515

(port.cc:607): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=54.202.150.65:53351, 5

(port.cc:1003): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(port.cc:607): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=54.202.150.65:53351, 0

(port.cc:1003): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:53351b

(port.cc:607): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=54.202.150.65:53351, b




(p2ptransportchannel.cc:1971): Selecting connection for triggered check: Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->]





(port.cc:1411): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(port.cc:1003): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:53351f

(port.cc:607): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Sent STUN ping response, to=54.202.150.65:53351, f




(port.cc:413): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received STUN binding error: class=4 number=0 reas1

(port.cc:413): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received STUN binding error: class=4 number=0 reas1





(port.cc:1379): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533518

(port.cc:413): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received STUN binding error: class=4 number=0 reas1

(port.cc:1379): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:533510

(port.cc:1394): Jingle:Conn[0x25105930:sdparta_0:rCQwcgOu:1:0:local:udp:192.168.0.19:36471->hlNbn+l3:1:92217087:relay:udp:54.202.150.65:53351n




(port.cc:1457): Connection deleted with number of pings sent: 15

(p2ptransportchannel.cc:1820): Jingle:Channel[sdparta_0|1|R_]: Removed connection 0x25105930 (0 remaining)


--can you please help me how to debug this situation? It was a working connection what could have changed.


(p2ptransportchannel.cc:1410): Jingle:Channel[sdparta_0|1|R_]: Transport channel state changed from 2 to 3





(transportcontroller.cc:639): sdparta_0 TransportChannel 1 state changed. Check if state is complete.

(messagequeue.cc:537): Message took 280ms to dispatch. Posted from: Destroy@../../webrtc/p2p/base/port.cc:1124

(messagequeue.cc:537): Message took 59ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877



(port.cc:413): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received STUN binding error: class=4 number=0 reas1

(port.cc:329): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received unexpected STUN message type (273) from u)

(port.cc:413): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received STUN binding error: class=4 number=0 reas1

(port.cc:329): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received unexpected STUN message type (273) from u)

(port.cc:413): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Net[eth0:192.168.0.0/24:Unknown]]: Received STUN binding error: class=4 number=0 reas1

(port.cc:329): Jingle:Port[0x2cf3dc0:sdparta_0:1:0:local:Ne

t[eth0:192.168.0.0/24:Unknown]]: Received unexpected STUN message type (273) from u)

(messagequeue.cc:537): Message took 232ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 593ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 201ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 268ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 179ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 245ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 162ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877




(sctpdataengine.cc:855): Unknown SCTP event: 2




(messagequeue.cc:537): Message took 175ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 185ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 488ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 162ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544

(messagequeue.cc:537): Message took 148ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 58ms to dispatch. Posted from: OnSctpOutboundPacket@../../webrtc/media/sctp/sctpdataengine.cc:205




(sctpdataengine.cc:838): SCTP_SEND_FAILED_EVENT

(sctpdataengine.cc:838): SCTP_SEND_FAILED_EVENT

(sctpdataengine.cc:838): SCTP_SEND_FAILED_EVENT

(sctpdataengine.cc:838): SCTP_SEND_FAILED_EVENT

(sctpdataengine.cc:838): SCTP_SEND_FAILED_EVENT

(sctpdataengine.cc:838): SCTP_SEND_FAILED_EVENT

(sctpdataengine.cc:838): SCTP_SEND_FAILED_EVENT

(sctpdataengine.cc:838): SCTP_SEND_FAILED_EVENT

(sctpdataengine.cc:868): Association change SCTP_COMM_LOST




(messagequeue.cc:537): Message took 160ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 637ms to dispatch. Posted from: UpdateNetworksContinually@../../webrtc/base/network.cc:877

(messagequeue.cc:537): Message took 102ms to dispatch. Posted from: OnCheckAndPing@../../webrtc/p2p/base/p2ptransportchannel.cc:1544


.....continues with the same log forever.....







-------------------------------

WebRTCBud

unread,
Apr 28, 2017, 3:20:11 PM4/28/17
to discuss-webrtc
Hello Nils,

Today I have built the WebRTC source code and tried the setup on a linux box, I have similar logs with the connection getting disconnected.

Do you have any clues for me to debug the issue?

thank you in advance.

WebRTCBud

unread,
Apr 28, 2017, 3:20:16 PM4/28/17
to discuss-webrtc
Can somebody help me how to debug this issue? 

I have a big WebRTC demo blocked because of this disconnection issue.

Taylor Brandstetter

unread,
Apr 28, 2017, 7:02:17 PM4/28/17
to discuss-webrtc
The log from your last message indicates that ICE timed out without receiving a response. But there are some odd things logged later that stand out to me:
  • Lots of "message took Xms to dispatch" messages. Our library uses message loops heavily, and this log is printed if any individual message takes more than 50ms to dispatch (since that can be an indication that something is taking longer than we expect it to). The fact that this log message is printed so many times, with times upwards of 1 second, seems to indicate something is causing the entire process to run slowly. Which could explain the problem, if it results in message queues filling up. Though, maybe these messages are just flukes; it's not obvious how often it actually happens, since the log messages don't have timestamps.
  • The STUN error. I'm curious what the "reason" is; it seems log messages more than ~140 characters are getting cut off by something.
  • "Received unexpected STUN message type (273)". 273 is a binding error response; but the connection timed out further up in the log, which means something is causing the response to arrive (or at least be processed) very late.
To get to the bottom of this, could you collect a webrtc log with non-truncated messages (and preferably with timestamps), as well as a packet capture, and attach them to a new webrtc bug, adding the "Network" component? The packet capture could tell us if the responses are actually arriving late, or if something else is going on. It may help to get the same for the Chrome side as well.

--

---
You received this message because you are subscribed to the Google Groups "discuss-webrtc" group.
To unsubscribe from this group and stop receiving emails from it, send an email to discuss-webrtc+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/discuss-webrtc/66a0176b-8a30-4be1-a9c0-312339952500%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

WebRTCBud

unread,
May 8, 2017, 8:31:20 AM5/8/17
to discuss-webrtc
Dear Taylor,

After some difficulty we were able to get the wireshark traces and webrtc logs from both the peers. I observe that the connection ran for few hours hence the wireshark log data is huge to attach directly, I had to put it on a hosting service to file the bug.

I did not have success in getting the time stamped logs as you requested, I must be missing something. I am going to continue my understanding on this using a "C" application.


Let me know if I can be of any other help to get to the bottom of this issue.

To unsubscribe from this group and stop receiving emails from it, send an email to discuss-webrt...@googlegroups.com.
Reply all
Reply to author
Forward
0 new messages