Split proxy activity notices; proxy bug fixes

- Split proxy activity notice, following NoticeBytesTransferred,
  NoticeTotalBytesTransferred pattern
- Fix doNetworkDiscovery run once flag
- Rename Proxy.nextAnnounceTime to Proxy.nextAnnounceNotBefore
- Fix next-announce-delay case: reset delay after broker client is reset

psiphon/common/inproxy/brokerClient.go

@@ -116,7 +116,9 @@ func (b *BrokerClient) ProxyAnnounce(
 
 	// Increase the timeout to account for requestDelay, which is applied
 	// before the actual network round trip.
-	timeout += requestDelay
+	if requestDelay > 0 {
+		timeout += requestDelay
+	}
 
 	requestCtx, requestCancelFunc := context.WithTimeout(ctx, timeout)
 	defer requestCancelFunc()

psiphon/common/inproxy/client.go

@@ -169,7 +169,7 @@ func DialClient(
 		// fail, WebRTCDialCoordinator STUNServerAddressFailed will be
 		// invoked, giving the Psiphon client an opportunity to select new
 		// STUN server parameter -- although, in this failure case, the
-		// WebRTC connection attemp can succeed with other ICE candidates or
+		// WebRTC connection attempt can succeed with other ICE candidates or
 		// no ICE candidates.
 
 		err := ctx.Err()

psiphon/common/inproxy/proxy.go

@@ -62,8 +62,9 @@ type Proxy struct {
 	networkDiscoveryRunOnce   bool
 	networkDiscoveryNetworkID string
 
-	nextAnnounceMutex sync.Mutex
-	nextAnnounceTime  time.Time
+	nextAnnounceMutex        sync.Mutex
+	nextAnnounceBrokerClient *BrokerClient
+	nextAnnounceNotBefore    time.Time
 }
 
 // TODO: add PublicNetworkAddress/ListenNetworkAddress to facilitate manually
@@ -441,6 +442,7 @@ func (p *Proxy) doNetworkDiscovery(
 	}()
 	waitGroup.Wait()
 
+	p.networkDiscoveryRunOnce = true
 	p.networkDiscoveryNetworkID = networkID
 }
 
@@ -543,17 +545,24 @@ func (p *Proxy) proxyOneClient(
 	announceDelay, announceDelayJitter := p.getAnnounceDelayParameters()
 	p.nextAnnounceMutex.Lock()
 	delay := prng.JitterDuration(announceDelay, announceDelayJitter)
-	if p.nextAnnounceTime.IsZero() {
-		// No delay for the very first announce request.
-		p.nextAnnounceTime = time.Now().Add(delay)
-
+	if p.nextAnnounceBrokerClient != brokerClient {
+		// Reset the delay when the broker client changes.
+		p.nextAnnounceNotBefore = time.Time{}
+		p.nextAnnounceBrokerClient = brokerClient
+	}
+	if p.nextAnnounceNotBefore.IsZero() {
+		p.nextAnnounceNotBefore = time.Now().Add(delay)
+		// No delay for the very first announce request, so leave
+		// announceRequestDelay set to 0.
 	} else {
-		announceRequestDelay = time.Until(p.nextAnnounceTime)
+		announceRequestDelay = time.Until(p.nextAnnounceNotBefore)
 		if announceRequestDelay < 0 {
-			p.nextAnnounceTime = time.Now().Add(delay)
+			// This announce did not arrive until after the next delay already
+			// passed, so proceed with no delay.
+			p.nextAnnounceNotBefore = time.Now().Add(delay)
 			announceRequestDelay = 0
 		} else {
-			p.nextAnnounceTime = p.nextAnnounceTime.Add(delay)
+			p.nextAnnounceNotBefore = p.nextAnnounceNotBefore.Add(delay)
 		}
 	}
 	p.nextAnnounceMutex.Unlock()

psiphon/common/parameters/parameters.go

@@ -423,6 +423,7 @@ const (
 	InproxyClientWebRTCAwaitDataChannelTimeout         = "InproxyClientWebRTCAwaitDataChannelTimeout"
 	InproxyProxyDestinationDialTimeout                 = "InproxyProxyDestinationDialTimeout"
 	InproxyPsiphonAPIRequestTimeout                    = "InproxyPsiphonAPIRequestTimeout"
+	InproxyProxyTotalActivityNoticePeriod              = "InproxyProxyTotalActivityNoticePeriod"
 
 	// Retired parameters
 
@@ -876,12 +877,12 @@ var defaultParameters = map[string]struct {
 	InproxyBrokerClientOfferTimeout:                    {value: 10 * time.Second, minimum: time.Duration(0), flags: serverSideOnly},
 	InproxyBrokerPendingServerRequestsTTL:              {value: 60 * time.Second, minimum: time.Duration(0), flags: serverSideOnly},
 	InproxyProxyAnnounceRequestTimeout:                 {value: 2*time.Minute + 10*time.Second, minimum: time.Duration(0)},
-	InproxyProxyAnnounceDelay:                          {value: 1 * time.Second, minimum: time.Duration(0)},
+	InproxyProxyAnnounceDelay:                          {value: 100 * time.Millisecond, minimum: time.Duration(0)},
 	InproxyProxyAnnounceDelayJitter:                    {value: 0.5, minimum: 0.0},
 	InproxyProxyAnswerRequestTimeout:                   {value: 10*time.Second + 10*time.Second, minimum: time.Duration(0)},
 	InproxyClientOfferRequestTimeout:                   {value: 10*time.Second + 10*time.Second, minimum: time.Duration(0)},
-	InproxyClientOfferRetryDelay:                       {value: 1 * time.Second, minimum: time.Duration(0)},
-	InproxyClientOfferRetryJitter:                      {value: 0.3, minimum: 0.0},
+	InproxyClientOfferRetryDelay:                       {value: 100 * time.Millisecond, minimum: time.Duration(0)},
+	InproxyClientOfferRetryJitter:                      {value: 0.5, minimum: 0.0},
 	InproxyClientRelayedPacketRequestTimeout:           {value: 10 * time.Second, minimum: time.Duration(0)},
 	InproxyBrokerRoundTripStatusCodeFailureThreshold:   {value: 2 * time.Second, minimum: time.Duration(0), flags: useNetworkLatencyMultiplier},
 	InproxyDTLSRandomizationProbability:                {value: 0.5, minimum: 0.0},
@@ -904,6 +905,7 @@ var defaultParameters = map[string]struct {
 	InproxyClientWebRTCAwaitDataChannelTimeout:         {value: 20 * time.Second, minimum: time.Duration(0), flags: useNetworkLatencyMultiplier},
 	InproxyProxyDestinationDialTimeout:                 {value: 20 * time.Second, minimum: time.Duration(0), flags: useNetworkLatencyMultiplier},
 	InproxyPsiphonAPIRequestTimeout:                    {value: 10 * time.Second, minimum: 1 * time.Second, flags: useNetworkLatencyMultiplier},
+	InproxyProxyTotalActivityNoticePeriod:              {value: 5 * time.Minute, minimum: 1 * time.Second},
 }
 
 // IsServerSideOnly indicates if the parameter specified by name is used

psiphon/config.go

@@ -484,7 +484,7 @@ type Config struct {
 	// distributed or displayed to users. Default is off.
 	EmitDiagnosticNetworkParameters bool
 
-	// EmitBytesTransferred indicates whether to emit periodic notices showing
+	// EmitBytesTransferred indicates whether to emit frequent notices showing
 	// bytes sent and received.
 	EmitBytesTransferred bool
 
@@ -659,6 +659,10 @@ type Config struct {
 	// proxy or proxies with the same personal compartment IDs.
 	InproxyClientPersonalCompartmentIDs []string
 
+	// EmitInproxyProxyActivity indicates whether to emit frequent notices
+	// showing proxy connection information and bytes transferred.
+	EmitInproxyProxyActivity bool
+
 	//
 	// The following parameters are deprecated.
 	//
@@ -993,8 +997,10 @@ type Config struct {
 	InproxyClientWebRTCAwaitDataChannelTimeoutMilliseconds *int
 	InproxyProxyDestinationDialTimeoutMilliseconds         *int
 	InproxyPsiphonAPIRequestTimeoutMilliseconds            *int
-	InproxySkipAwaitFullyConnected                         bool
-	InproxyEnableWebRTCDebugLogging                        bool
+	InproxyProxyTotalActivityNoticePeriodMilliseconds      *int
+
+	InproxySkipAwaitFullyConnected  bool
+	InproxyEnableWebRTCDebugLogging bool
 
 	// params is the active parameters.Parameters with defaults, config values,
 	// and, optionally, tactics applied.
@@ -2479,6 +2485,10 @@ func (config *Config) makeConfigParameters() map[string]interface{} {
 		applyParameters[parameters.InproxyPsiphonAPIRequestTimeout] = fmt.Sprintf("%dms", *config.InproxyPsiphonAPIRequestTimeoutMilliseconds)
 	}
 
+	if config.InproxyProxyTotalActivityNoticePeriodMilliseconds != nil {
+		applyParameters[parameters.InproxyProxyTotalActivityNoticePeriod] = fmt.Sprintf("%dms", *config.InproxyProxyTotalActivityNoticePeriodMilliseconds)
+	}
+
 	// When adding new config dial parameters that may override tactics, also
 	// update setDialParametersHash.
 

psiphon/controller.go

@@ -2583,6 +2583,43 @@ func (controller *Controller) runInproxyProxy() {
 	// and formatting when debug logging is off.
 	debugLogging := controller.config.InproxyEnableWebRTCDebugLogging
 
+	activityNoticePeriod := p.Duration(parameters.InproxyProxyTotalActivityNoticePeriod)
+	var lastActivityNotice time.Time
+	var lastActivityConnectingClients, lastActivityConnectedClients int32
+	var activityTotalBytesUp, activityTotalBytesDown int64
+	activityUpdater := func(
+		connectingClients int32,
+		connectedClients int32,
+		bytesUp int64,
+		bytesDown int64,
+		_ time.Duration) {
+
+		// This emit logic mirrors the logic for NoticeBytesTransferred and
+		// NoticeTotalBytesTransferred in tunnel.operateTunnel.
+
+		if controller.config.EmitInproxyProxyActivity &&
+			(bytesUp > 0 || bytesDown > 0) {
+
+			NoticeInproxyProxyActivity(
+				connectingClients, connectedClients, bytesUp, bytesDown)
+		}
+
+		activityTotalBytesUp += bytesUp
+		activityTotalBytesDown += bytesDown
+
+		if lastActivityNotice.Add(activityNoticePeriod).Before(time.Now()) ||
+			connectingClients != lastActivityConnectingClients ||
+			connectedClients != lastActivityConnectedClients {
+
+			NoticeInproxyProxyTotalActivity(
+				connectingClients, connectedClients,
+				activityTotalBytesUp, activityTotalBytesDown)
+			lastActivityNotice = time.Now()
+		}
+		lastActivityConnectingClients = connectingClients
+		lastActivityConnectedClients = connectedClients
+	}
+
 	config := &inproxy.ProxyConfig{
 		Logger:                        NoticeCommonLogger(debugLogging),
 		EnableWebRTCDebugLogging:      debugLogging,
@@ -2599,14 +2636,7 @@ func (controller *Controller) runInproxyProxy() {
 			NoticeInproxyOperatorMessage(messageJSON)
 		},
 
-		ActivityUpdater: func(
-			connectingClients int32,
-			connectedClients int32,
-			bytesUp int64,
-			bytesDown int64,
-			bytesDuration time.Duration) {
-			NoticeInproxyProxyActivity(connectingClients, connectedClients, bytesUp, bytesDown, bytesDuration)
-		},
+		ActivityUpdater: activityUpdater,
 	}
 
 	proxy, err := inproxy.NewProxy(config)
@@ -2620,6 +2650,11 @@ func (controller *Controller) runInproxyProxy() {
 
 	proxy.Run(controller.runCtx)
 
+	// Emit one last NoticeInproxyProxyTotalActivity with the final byte counts.
+	NoticeInproxyProxyTotalActivity(
+		lastActivityConnectingClients, lastActivityConnectedClients,
+		activityTotalBytesUp, activityTotalBytesDown)
+
 	NoticeInfo("inproxy proxy: stopped")
 }
 

psiphon/notice.go

@@ -1092,20 +1092,39 @@ func NoticeInproxyOperatorMessage(messageJSON string) {
 
 // NoticeInproxyProxyActivity reports proxy usage statistics. The stats are
 // for activity since the last NoticeInproxyProxyActivity report.
+//
+// This is not a diagnostic notice: the user app has requested this notice
+// with EmitproxyActivity for functionality such as traffic display; and this
+// frequent notice is not intended to be included with feedback.
 func NoticeInproxyProxyActivity(
 	connectingClients int32,
 	connectedClients int32,
 	bytesUp int64,
-	bytesDown int64,
-	bytesDuration time.Duration) {
+	bytesDown int64) {
 
 	singletonNoticeLogger.outputNotice(
 		"InproxyProxyActivity", noticeIsDiagnostic,
 		"connectingClients", connectingClients,
 		"connectedClients", connectedClients,
 		"bytesUp", bytesUp,
-		"bytesDown", bytesDown,
-		"bytesDuration", bytesDuration)
+		"bytesDown", bytesDown)
+}
+
+// NoticeInproxyProxyTotalActivity reports how many proxied bytes have been
+// transferred in total up to this point; in addition to current connection
+// status. This is a diagnostic notice.
+func NoticeInproxyProxyTotalActivity(
+	connectingClients int32,
+	connectedClients int32,
+	totalBytesUp int64,
+	totalBytesDown int64) {
+
+	singletonNoticeLogger.outputNotice(
+		"InproxyProxyTotalActivity", noticeIsDiagnostic,
+		"connectingClients", connectingClients,
+		"connectedClients", connectedClients,
+		"totalBytesUp", totalBytesUp,
+		"totalBytesDown", totalBytesDown)
 }
 
 type repetitiveNoticeState struct {

psiphon/server/server_test.go

@@ -1462,14 +1462,14 @@ func runServer(t *testing.T, runConfig *runServerConfig) {
 			case "Untunneled":
 				sendNotificationReceived(untunneledPortForward)
 
-			case "InproxyProxyActivity":
+			case "InproxyProxyTotalActivity":
 
 				// This assumes that both non-zero bytes up and down are
 				// reported in at least same notice, although there's some
 				// unlikely chance it's only one or the other.
 				connectedClients := int(payload["connectedClients"].(float64))
-				bytesUp := int(payload["bytesUp"].(float64))
-				bytesDown := int(payload["bytesDown"].(float64))
+				bytesUp := int(payload["totalBytesUp"].(float64))
+				bytesDown := int(payload["totalBytesDown"].(float64))
 				if connectedClients == 1 && bytesUp > 0 && bytesDown > 0 {
 					sendNotificationReceived(inproxyActivity)
 				}