Opened 2 years ago

Closed 13 days ago

#21305 closed defect (worksforme)

Client gets into an unrecoverable connect / close loop

Reported by: arlolra Owned by: cohosh
Priority: Medium Milestone:
Component: Obfuscation/Snowflake Version:
Severity: Normal Keywords:
Cc: arma Actual Points:
Parent ID: Points:
Reviewer: Sponsor: Sponsor19

Description

This was after briefly losing internet connectivity. It was just endlessly repeating this pattern. We tried giving it a new proxy to connect to but with no luck. Restarting the client immediately resolved the issue, so it seems to have got itself into a bad state.

2017/01/24 13:35:12 ---- Handler: closed ---
2017/01/24 13:35:12 SOCKS listening...
2017/01/24 13:35:12 SOCKS accepted:  {0.0.3.0:1  map[]}
2017/01/24 13:35:14 WebRTC: Collecting a new Snowflake. Currently at [0/1]
2017/01/24 13:35:14 snowflake-61xONPqOrMQ67aWl  connecting...
2017/01/24 13:35:14 WebRTC: PeerConnection created.
2017/01/24 13:35:14 WebRTC: OnNegotiationNeeded
2017/01/24 13:35:14 WebRTC: DataChannel created.
2017/01/24 13:35:14 candidate:4096217215 1 udp 2122260223 192.168.1.154 40594 typ host generation 0 ufrag ko968AKONjQ/Rpya network-id 1
2017/01/24 13:35:14 candidate:1970230987 1 udp 1686052607 108.16.226.229 40594 typ srflx raddr 192.168.1.154 rport 40594 generation 0 ufrag ko968AKONjQ/Rpya network-id 1
2017/01/24 13:35:14 candidate:3131354255 1 tcp 1518280447 192.168.1.154 53340 typ host tcptype passive generation 0 ufrag ko968AKONjQ/Rpya network-id 1
2017/01/24 13:35:14 WebRTC: OnIceComplete
2017/01/24 13:35:14 Negotiating via BrokerChannel...
Target URL:  snowflake-reg.appspot.com 
Front URL:   www.google.com
2017/01/24 13:35:14 BrokerChannel Response:
200 OK

2017/01/24 13:35:14 Received Answer:

v=0
o=mozilla...THIS_IS_SDPARTA-51.0 6797456362141212310 0 IN IP4 0.0.0.0
s=-
t=0 0
a=sendrecv
a=fingerprint:sha-256 A8:2C:FA:1D:33:46:8F:57:5D:56:AC:5C:EF:32:B5:8D:8E:2C:A5:FD:8E:33:6E:88:DD:5F:CC:4A:8B:02:BA:64
a=ice-options:trickle
a=msid-semantic:WMS *
m=application 38953 DTLS/SCTP 5000
c=IN IP4 88.159.72.23
a=candidate:0 1 UDP 2122252543 88.159.72.23 38953 typ host
a=sendrecv
a=end-of-candidates
a=ice-pwd:acc3c9ec8efb8d0a16a500203da69560
a=ice-ufrag:6cb61e26
a=mid:data
a=sctpmap:5000 webrtc-datachannel 256
a=setup:active
a=ssrc:2244974687 cname:{c72775ac-0151-48b1-9063-0922a11994e6}

2017/01/24 13:35:14 ---- Handler: snowflake assigned ----
2017/01/24 13:35:14 Buffered 218 bytes --> WebRTC
2017/01/24 13:35:14 WebRTC: DataChannel.OnOpen
2017/01/24 13:35:14 Flushed 218 bytes.
2017/01/24 13:35:16 Traffic Bytes (in|out): 749 | 218 -- (1 OnMessages, 1 Sends)
2017/01/24 13:35:23 Traffic Bytes (in|out): 4803 | 3907 -- (8 OnMessages, 7 Sends)
2017/01/24 13:35:24 WebRTC: At capacity [1/1]  Retrying in 10 seconds...
2017/01/24 13:35:34 WebRTC: At capacity [1/1]  Retrying in 10 seconds...
2017/01/24 13:35:44 WebRTC: At capacity [1/1]  Retrying in 10 seconds...
2017/01/24 13:35:49 WebRTC: No messages received for 30 seconds -- closing stale connection.
2017/01/24 13:35:49 WebRTC: closing DataChannel
2017/01/24 13:35:49 WebRTC: DataChannel.OnClose [locally]
2017/01/24 13:35:49 WebRTC: closing PeerConnection
2017/01/24 13:35:49 WebRTC: Closing
2017/01/24 13:35:49 copy loop ended

Child Tickets

Attachments (1)

snowflake.log (2.3 MB) - added by arlolra 2 years ago.

Change History (7)

Changed 2 years ago by arlolra

Attachment: snowflake.log added

comment:1 Changed 14 months ago by arlolra

We tried giving it a new proxy to connect to but with no luck.

It would be nice to confirm that the broker actually handed it this new proxy and it still couldn't shuttle data. Seems like this sort of situation is the reason for #25429 and we should maybe not be too hasty about ripping that code out.

comment:2 Changed 2 weeks ago by cohosh

Owner: set to cohosh
Status: newassigned

comment:3 Changed 2 weeks ago by cohosh

Hey, I'm working on reproducing this bug and after investigating these log messages from above:

2017/01/24 13:35:16 Traffic Bytes (in|out): 749 | 218 -- (1 OnMessages, 1 Sends)
2017/01/24 13:35:23 Traffic Bytes (in|out): 4803 | 3907 -- (8 OnMessages, 7 Sends)

It looks like your client is actually sending and receiving bytes correctly.

So when you were in this connect/close loop, were you unable to send and receive traffic? Or is this just usual behaviour like in #25429?

comment:4 Changed 2 weeks ago by arlolra

So when you were in this connect/close loop, were you unable to send and receive traffic?

This was @arma's client and I believe they refreshed their browser window a few times to no avail.

But note that this was during a period of time when the standalone go-proxies that we're running (and currently handle the majority of capacity) were in a pretty unreliable state and we did not confirm that the new proxy we tried to hand them was the one they actually connected to in that log.

Maybe they just got lucky when restarting the client?

Or is this just usual behaviour like in #25429?

For the most part, yes. The suspicious thing is that they suddenly received a proxy that was able to send messages upon restarting.

Short of manual inspection, you could try establishing a connection and then disconnecting your network, waiting a bit, and reconnecting a few times to see if it's reproducible. Otherwise, feel free to close it as "worksforme". If it's really a client issue, it'll rear its head again and we'll have fresher data to work with.

comment:5 Changed 13 days ago by gaba

Sponsor: Sponsor19

comment:6 in reply to:  4 Changed 13 days ago by cohosh

Resolution: worksforme
Status: assignedclosed

Replying to arlolra:

Short of manual inspection, you could try establishing a connection and then disconnecting your network, waiting a bit, and reconnecting a few times to see if it's reproducible. Otherwise, feel free to close it as "worksforme". If it's really a client issue, it'll rear its head again and we'll have fresher data to work with.

Thanks! I tried for a while to reproduce this yesterday with no luck. However, I do notice #23780 occurring very quickly when there are connection problems. This on its own doesn't have any affect other than warnings with the default setting of disabling PathBias. However, there is a general problem of the client being unaware of the connection state to the proxy (as in #25429) and unable to tell the difference between bridge failure and proxy failure (although proxy failure is much more likely).

I'm going to close this ticket since so much has changed and instead focus on #25429 and reconsider opening another ticket related to #23780.

Note: See TracTickets for help on using tickets.