[tor-bugs] #34080 [Circumvention/Snowflake]: Avoid double delays from ReconnectTimeout

[Tor Bug Tracker & Wiki]

#34080: Avoid double delays from ReconnectTimeout
-----------------------------------------+--------------------
     Reporter:  dcf                      |      Owner:  (none)
         Type:  defect                   |     Status:  new
     Priority:  Medium                   |  Milestone:
    Component:  Circumvention/Snowflake  |    Version:
     Severity:  Normal                   |   Keywords:
Actual Points:                           |  Parent ID:
       Points:                           |   Reviewer:
      Sponsor:                           |
-----------------------------------------+--------------------
 [https://gitweb.torproject.org/pluggable-
 transports/snowflake.git/tree/client/lib/snowflake.go?id=72cfb96edeb7c9a3c93d38539bc31a51e30dbe8d#n18
 ReconnectTimeout] is used in 2 places:
  * In [https://gitweb.torproject.org/pluggable-
 transports/snowflake.git/tree/client/lib/webrtc.go?id=72cfb96edeb7c9a3c93d38539bc31a51e30dbe8d#n223
 exchangeSDP], where it is a delay inserted between calls to
 `broker.Negotiate` until one of them succeeds.
    {{{
 Failed to retrieve answer. Retrying in 10s
    }}}
  * In the main [https://gitweb.torproject.org/pluggable-
 transports/snowflake.git/tree/client/snowflake.go?id=72cfb96edeb7c9a3c93d38539bc31a51e30dbe8d#n27
 ConnectLoop], where it is a delay inserted between every check for getting
 a new snowflake.
    {{{
 WebRTC: <errmsg>  Retrying in 10s...
    }}}

 The broker itself also terminates requests after 10s when the chosen proxy
 doesn't respond: `BrokerChannel Response: 504 Gateway Timeout`.

 This situation sometimes results in double delays. Here are two cases I've
 identified.
  * The client requests a proxy, the broker responds immediately with an
 answer, but the proxy doesn't work. After waiting the `DataChannelTimeout`
 to decide that the proxy doesn't work, the client waits an ''additional''
 `ReconnectTimeout` in `ConnectLoop`.
    Here, I've set `DataChannelTimeout` to 10s. Notice that between
 `DataChannel created` and `Collecting a new Snowflake` there are 20s
 (which is `DataChannelTimeout` + `ReconnectTimeout`), when it really
 should only be 10s.
    {{{
 2020/04/30 22:38:29 Received Answer.
 2020/04/30 22:38:29 WebRTC: DataChannel created.
 2020/04/30 22:38:39 establishDataChannel: timeout waiting for
 DataChannel.OnOpen
 2020/04/30 22:38:39 WebRTC: closing PeerConnection
 2020/04/30 22:38:39 WebRTC: Closing
 2020/04/30 22:38:39 WebRTC: WebRTC: Could not establish DataChannel
 Retrying in 10s...
 2020/04/30 22:38:49 WebRTC: Collecting a new Snowflake. Currently at [0/1]
 }}}
  * The client requests a proxy, and the broker waits for 10s to respond
 with a 504 Gateway Timeout (indicating that the chosen proxy did not
 return an answer to the broker in time). The client waits 10s for the
 broker to respond, then waits another `ReconnectTimeout` in exchangeSDP
 before trying the broker again.
    {{{
 2020/04/30 22:39:30 Negotiating via BrokerChannel...
 2020/04/30 22:39:41 BrokerChannel Response: 504 Gateway Timeout
 2020/04/30 22:39:41 BrokerChannel Error: Unexpected error, no answer.
 2020/04/30 22:39:41 Failed to retrieve answer. Retrying in 10s
 2020/04/30 22:39:51 Negotiating via BrokerChannel...
    }}}

 Both these cases can probably be fixed by running the timer in parallel
 with the periodic operation they are rate limiting. That is, instead of
 {{{
 for {
         operation()
         <-time.After(ReconnectTimeout)
 }
 }}}
 it can be
 {{{
 for {
         timer := time.After(ReconnectTimeout)
         operation()
         <-timer
 }
 }}}
 That way, if the operation itself takes more than 10s, `ReconnectTimeout`
 doesn't impose any additional delay.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/34080>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online