Browse Source

Retire/disable stats

- Don't record or send "session" events.
  Delete any existing records.
  Discard when received from old client.

- Don't send "bytes_transferred" stats.
  Discard when received from old client.

- When no domain regexes are received,
  don't record any host bytes, including
  (OTHER); in this case no "domain_bytes"
  will be sent.

- Skip the status request entirely when
  there are no domain_bytes or persistent
  event records to report.
Rod Hynes 8 years ago
parent
commit
e3fa9574ec
6 changed files with 93 additions and 252 deletions
  1. 23 4
      psiphon/dataStore.go
  2. 4 101
      psiphon/server/api.go
  3. 28 73
      psiphon/serverApi.go
  4. 21 16
      psiphon/transferstats/collector.go
  5. 17 2
      psiphon/transferstats/conn.go
  6. 0 56
      psiphon/tunnel.go

+ 23 - 4
psiphon/dataStore.go

@@ -66,7 +66,6 @@ const (
 const (
 	DATA_STORE_LAST_CONNECTED_KEY           = "lastConnected"
 	DATA_STORE_LAST_SERVER_ENTRY_FILTER_KEY = "lastServerEntryFilter"
-	PERSISTENT_STAT_TYPE_TUNNEL             = tunnelStatsBucket
 	PERSISTENT_STAT_TYPE_REMOTE_SERVER_LIST = remoteServerListStatsBucket
 )
 
@@ -153,6 +152,24 @@ func InitDataStore(config *Config) (err error) {
 			return
 		}
 
+		// Cleanup obsolete tunnel (session) stats bucket, if one still exists
+
+		err = db.Update(func(tx *bolt.Tx) error {
+			tunnelStatsBucket := []byte("tunnelStats")
+			if tx.Bucket(tunnelStatsBucket) != nil {
+				err := tx.DeleteBucket(tunnelStatsBucket)
+				if err != nil {
+					NoticeAlert("DeleteBucket %s error: %s", tunnelStatsBucket, err)
+					// Continue, since this is not fatal
+				}
+			}
+			return nil
+		})
+		if err != nil {
+			err = fmt.Errorf("initDataStore failed to create buckets: %s", err)
+			return
+		}
+
 		singleton.db = db
 
 		// The migrateServerEntries function requires the data store is
@@ -985,7 +1002,6 @@ var persistentStatStateReporting = []byte("1")
 
 var persistentStatTypes = []string{
 	PERSISTENT_STAT_TYPE_REMOTE_SERVER_LIST,
-	PERSISTENT_STAT_TYPE_TUNNEL,
 }
 
 // StorePersistentStat adds a new persistent stat record, which
@@ -1065,8 +1081,6 @@ func TakeOutUnreportedPersistentStats(maxCount int) (map[string][][]byte, error)
 
 		for _, statType := range persistentStatTypes {
 
-			stats[statType] = make([][]byte, 0)
-
 			bucket := tx.Bucket([]byte(statType))
 			cursor := bucket.Cursor()
 			for key, value := cursor.First(); key != nil; key, value = cursor.Next() {
@@ -1090,6 +1104,11 @@ func TakeOutUnreportedPersistentStats(maxCount int) (map[string][][]byte, error)
 					// Must make a copy as slice is only valid within transaction.
 					data := make([]byte, len(key))
 					copy(data, key)
+
+					if stats[statType] == nil {
+						stats[statType] = make([][]byte, 0)
+					}
+
 					stats[statType] = append(stats[statType], data)
 					count += 1
 				}

+ 4 - 101
psiphon/server/api.go

@@ -341,26 +341,13 @@ func statusAPIRequestHandler(
 
 	logQueue := make([]LogFields, 0)
 
-	// Overall bytes transferred stats
-
-	bytesTransferred, err := getInt64RequestParam(statusData, "bytes_transferred")
-	if err != nil {
-		return nil, common.ContextError(err)
-	}
-
-	bytesTransferredFields := getRequestLogFields(
-		"bytes_transferred",
-		geoIPData,
-		authorizedAccessTypes,
-		params,
-		statusRequestParams)
-
-	bytesTransferredFields["bytes"] = bytesTransferred
-	logQueue = append(logQueue, bytesTransferredFields)
-
 	// Domain bytes transferred stats
 	// Older clients may not submit this data
 
+	// TODO: ignore these stats if regexes for client were empty; in this
+	// case, clients are expected to send no host_bytes, but older clients
+	// may still send.
+
 	if statusData["host_bytes"] != nil {
 
 		hostBytes, err := getMapStringInt64RequestParam(statusData, "host_bytes")
@@ -383,90 +370,6 @@ func statusAPIRequestHandler(
 		}
 	}
 
-	// Tunnel duration and bytes transferred stats
-	// Older clients may not submit this data
-
-	if statusData["tunnel_stats"] != nil {
-
-		tunnelStats, err := getJSONObjectArrayRequestParam(statusData, "tunnel_stats")
-		if err != nil {
-			return nil, common.ContextError(err)
-		}
-		for _, tunnelStat := range tunnelStats {
-
-			sessionFields := getRequestLogFields(
-				"session",
-				geoIPData,
-				authorizedAccessTypes,
-				params,
-				statusRequestParams)
-
-			sessionID, err := getStringRequestParam(tunnelStat, "session_id")
-			if err != nil {
-				return nil, common.ContextError(err)
-			}
-			sessionFields["session_id"] = sessionID
-
-			tunnelNumber, err := getInt64RequestParam(tunnelStat, "tunnel_number")
-			if err != nil {
-				return nil, common.ContextError(err)
-			}
-			sessionFields["tunnel_number"] = tunnelNumber
-
-			tunnelServerIPAddress, err := getStringRequestParam(tunnelStat, "tunnel_server_ip_address")
-			if err != nil {
-				return nil, common.ContextError(err)
-			}
-			sessionFields["tunnel_server_ip_address"] = tunnelServerIPAddress
-
-			// Note: older clients won't send establishment_duration
-			if _, ok := tunnelStat["establishment_duration"]; ok {
-
-				strEstablishmentDuration, err := getStringRequestParam(tunnelStat, "establishment_duration")
-				if err != nil {
-					return nil, common.ContextError(err)
-				}
-				establishmentDuration, err := strconv.ParseInt(strEstablishmentDuration, 10, 64)
-				if err != nil {
-					return nil, common.ContextError(err)
-				}
-				// Client reports establishment_duration in nanoseconds; divide to get to milliseconds
-				sessionFields["establishment_duration"] = establishmentDuration / 1000000
-			}
-
-			serverHandshakeTimestamp, err := getStringRequestParam(tunnelStat, "server_handshake_timestamp")
-			if err != nil {
-				return nil, common.ContextError(err)
-			}
-			sessionFields["server_handshake_timestamp"] = serverHandshakeTimestamp
-
-			strDuration, err := getStringRequestParam(tunnelStat, "duration")
-			if err != nil {
-				return nil, common.ContextError(err)
-			}
-			duration, err := strconv.ParseInt(strDuration, 10, 64)
-			if err != nil {
-				return nil, common.ContextError(err)
-			}
-			// Client reports duration in nanoseconds; divide to get to milliseconds
-			sessionFields["duration"] = duration / 1000000
-
-			totalBytesSent, err := getInt64RequestParam(tunnelStat, "total_bytes_sent")
-			if err != nil {
-				return nil, common.ContextError(err)
-			}
-			sessionFields["total_bytes_sent"] = totalBytesSent
-
-			totalBytesReceived, err := getInt64RequestParam(tunnelStat, "total_bytes_received")
-			if err != nil {
-				return nil, common.ContextError(err)
-			}
-			sessionFields["total_bytes_received"] = totalBytesReceived
-
-			logQueue = append(logQueue, sessionFields)
-		}
-	}
-
 	// Remote server list download stats
 	// Older clients may not submit this data
 

+ 28 - 73
psiphon/serverApi.go

@@ -317,6 +317,12 @@ func (serverContext *ServerContext) DoStatusRequest(tunnel *Tunnel) error {
 		return common.ContextError(err)
 	}
 
+	// Skip the request when there's no payload to send.
+
+	if len(statusPayload) == 0 {
+		return nil
+	}
+
 	if serverContext.psiphonHttpsClient == nil {
 
 		rawMessage := json.RawMessage(statusPayload)
@@ -401,6 +407,8 @@ func makeStatusRequestPayload(
 	serverId string) ([]byte, *statusRequestPayloadInfo, error) {
 
 	transferStats := transferstats.TakeOutStatsForServer(serverId)
+	hostBytes := transferStats.GetStatsForStatusRequest()
+
 	persistentStats, err := TakeOutUnreportedPersistentStats(
 		PSIPHON_API_PERSISTENT_STATS_MAX_COUNT)
 	if err != nil {
@@ -409,21 +417,25 @@ func makeStatusRequestPayload(
 		persistentStats = nil
 		// Proceed with transferStats only
 	}
+
+	if len(hostBytes) == 0 && len(persistentStats) == 0 {
+		// There is no payload to send.
+		return nil, nil, nil
+	}
+
 	payloadInfo := &statusRequestPayloadInfo{
 		serverId, transferStats, persistentStats}
 
 	payload := make(map[string]interface{})
 
-	hostBytes, bytesTransferred := transferStats.GetStatsForStatusRequest()
 	payload["host_bytes"] = hostBytes
-	payload["bytes_transferred"] = bytesTransferred
 
-	// We're not recording these fields, but the server requires them.
+	// We're not recording these fields, but legacy servers require them.
+	payload["bytes_transferred"] = 0
 	payload["page_views"] = make([]string, 0)
 	payload["https_requests"] = make([]string, 0)
 
 	persistentStatPayloadNames := make(map[string]string)
-	persistentStatPayloadNames[PERSISTENT_STAT_TYPE_TUNNEL] = "tunnel_stats"
 	persistentStatPayloadNames[PERSISTENT_STAT_TYPE_REMOTE_SERVER_LIST] = "remote_server_list_stats"
 
 	for statType, stats := range persistentStats {
@@ -469,26 +481,19 @@ func confirmStatusRequestPayload(payloadInfo *statusRequestPayloadInfo) {
 	}
 }
 
-// RecordTunnelStat records a tunnel duration and bytes
-// sent and received for subsequent reporting and quality
-// analysis.
-//
-// Tunnel durations are precisely measured client-side
-// and reported in status requests. As the duration is
-// not determined until the tunnel is closed, tunnel
-// stats records are stored in the persistent datastore
-// and reported via subsequent status requests sent to any
-// Psiphon server.
+// RecordRemoteServerListStat records a completed common or OSL
+// remote server list resource download.
 //
-// Since the status request that reports a tunnel stats
-// record is not necessarily handled by the same server, the
-// tunnel stats records include the original server ID.
+// The RSL download event could occur when the client is unable
+// to immediately send a status request to a server, so these
+// records are stored in the persistent datastore and reported
+// via subsequent status requests sent to any Psiphon server.
 //
-// Other fields that may change between tunnel stats recording
-// and reporting include client geo data, propagation channel,
-// sponsor ID, client version. These are not stored in the
-// datastore (client region, in particular, since that would
-// create an on-disk record of user location).
+// Note that common event field values may change between the
+// stat recording and reporting include client geo data,
+// propagation channel, sponsor ID, client version. These are not
+// stored in the datastore (client region, in particular, since
+// that would create an on-disk record of user location).
 // TODO: the server could encrypt, with a nonce and key unknown to
 // the client, a blob containing this data; return it in the
 // handshake response; and the client could store and later report
@@ -497,63 +502,13 @@ func confirmStatusRequestPayload(payloadInfo *statusRequestPayloadInfo) {
 // Multiple "status" requests may be in flight at once (due
 // to multi-tunnel, asynchronous final status retry, and
 // aggressive status requests for pre-registered tunnels),
-// To avoid duplicate reporting, tunnel stats records are
+// To avoid duplicate reporting, persistent stats records are
 // "taken-out" by a status request and then "put back" in
 // case the request fails.
 //
-// Note: since tunnel stats records have a globally unique
-// identifier (sessionId + tunnelNumber), we could tolerate
-// duplicate reporting and filter our duplicates on the
-// server-side. Permitting duplicate reporting could increase
-// the velocity of reporting (for example, both the asynchronous
-// untunneled final status requests and the post-connected
-// immediate status requests could try to report the same tunnel
-// stats).
 // Duplicate reporting may also occur when a server receives and
 // processes a status request but the client fails to receive
 // the response.
-func RecordTunnelStat(
-	sessionId string,
-	tunnelNumber int64,
-	tunnelServerIpAddress string,
-	establishmentDuration string,
-	serverHandshakeTimestamp string,
-	tunnelDuration string,
-	totalBytesSent int64,
-	totalBytesReceived int64) error {
-
-	tunnelStat := struct {
-		SessionId                string `json:"session_id"`
-		TunnelNumber             int64  `json:"tunnel_number"`
-		TunnelServerIpAddress    string `json:"tunnel_server_ip_address"`
-		EstablishmentDuration    string `json:"establishment_duration"`
-		ServerHandshakeTimestamp string `json:"server_handshake_timestamp"`
-		Duration                 string `json:"duration"`
-		TotalBytesSent           int64  `json:"total_bytes_sent"`
-		TotalBytesReceived       int64  `json:"total_bytes_received"`
-	}{
-		sessionId,
-		tunnelNumber,
-		tunnelServerIpAddress,
-		establishmentDuration,
-		serverHandshakeTimestamp,
-		tunnelDuration,
-		totalBytesSent,
-		totalBytesReceived,
-	}
-
-	tunnelStatJson, err := json.Marshal(tunnelStat)
-	if err != nil {
-		return common.ContextError(err)
-	}
-
-	return StorePersistentStat(
-		PERSISTENT_STAT_TYPE_TUNNEL, tunnelStatJson)
-}
-
-// RecordRemoteServerListStat records a completed common or OSL
-// remote server list resource download. These stats use the same
-// persist-until-reported mechanism described in RecordTunnelStats.
 func RecordRemoteServerListStat(
 	url, etag string) error {
 

+ 21 - 16
psiphon/transferstats/collector.go

@@ -49,18 +49,16 @@ type AccumulatedStats struct {
 
 // GetStatsForStatusRequest summarizes AccumulatedStats data as
 // required for the Psiphon Server API status request.
-func (stats AccumulatedStats) GetStatsForStatusRequest() (map[string]int64, int64) {
+func (stats AccumulatedStats) GetStatsForStatusRequest() map[string]int64 {
 
 	hostBytes := make(map[string]int64)
-	bytesTransferred := int64(0)
 
 	for hostname, hostStats := range stats.hostnameToStats {
 		totalBytes := hostStats.numBytesReceived + hostStats.numBytesSent
-		bytesTransferred += totalBytes
 		hostBytes[hostname] = totalBytes
 	}
 
-	return hostBytes, bytesTransferred
+	return hostBytes
 }
 
 // serverStats holds per-server stats.
@@ -92,14 +90,10 @@ type statsUpdate struct {
 // recordStats makes sure the given stats update is added to the global
 // collection. recentBytes are not adjusted when isPutBack is true,
 // as recentBytes aren't subject to TakeOut/PutBack.
-func recordStat(stat *statsUpdate, isPutBack bool) {
+func recordStat(stat *statsUpdate, isRecordingHostBytes, isPutBack bool) {
 	allStats.statsMutex.Lock()
 	defer allStats.statsMutex.Unlock()
 
-	if stat.hostname == "" {
-		stat.hostname = "(OTHER)"
-	}
-
 	storedServerStats := allStats.serverIDtoStats[stat.serverID]
 	if storedServerStats == nil {
 		storedServerStats = &serverStats{
@@ -108,14 +102,21 @@ func recordStat(stat *statsUpdate, isPutBack bool) {
 		allStats.serverIDtoStats[stat.serverID] = storedServerStats
 	}
 
-	storedHostStats := storedServerStats.accumulatedStats.hostnameToStats[stat.hostname]
-	if storedHostStats == nil {
-		storedHostStats = &hostStats{}
-		storedServerStats.accumulatedStats.hostnameToStats[stat.hostname] = storedHostStats
-	}
+	if isRecordingHostBytes {
 
-	storedHostStats.numBytesSent += stat.numBytesSent
-	storedHostStats.numBytesReceived += stat.numBytesReceived
+		if stat.hostname == "" {
+			stat.hostname = "(OTHER)"
+		}
+
+		storedHostStats := storedServerStats.accumulatedStats.hostnameToStats[stat.hostname]
+		if storedHostStats == nil {
+			storedHostStats = &hostStats{}
+			storedServerStats.accumulatedStats.hostnameToStats[stat.hostname] = storedHostStats
+		}
+
+		storedHostStats.numBytesSent += stat.numBytesSent
+		storedHostStats.numBytesReceived += stat.numBytesReceived
+	}
 
 	if !isPutBack {
 		storedServerStats.recentBytesSent += stat.numBytesSent
@@ -179,6 +180,10 @@ func PutBackStatsForServer(serverID string, accumulatedStats *AccumulatedStats)
 				numBytesSent:     hoststats.numBytesSent,
 				numBytesReceived: hoststats.numBytesReceived,
 			},
+			// We can set isRecordingHostBytes to true, regardless of whether there
+			// are any regexes, since there will be no host bytes to put back if they
+			// are not being recorded.
+			true,
 			true)
 	}
 }

+ 17 - 2
psiphon/transferstats/conn.go

@@ -59,6 +59,16 @@ func NewConn(nextConn net.Conn, serverID string, regexps *Regexps) *Conn {
 	}
 }
 
+func (conn *Conn) isRecordingHostBytes() bool {
+
+	// When there are no regexes, no per-host bytes stats will be
+	// recorded, including no "(OTHER)" category. In this case, it's
+	// expected that there will be no data to send in any status
+	// request.
+
+	return conn.regexps != nil && len(*conn.regexps) > 0
+}
+
 // Write is called when requests are being written out through the tunnel to
 // the remote server.
 func (conn *Conn) Write(buffer []byte) (n int, err error) {
@@ -68,9 +78,12 @@ func (conn *Conn) Write(buffer []byte) (n int, err error) {
 	// Count stats before we check the error condition. It could happen that the
 	// buffer was partially written and then an error occurred.
 	if n > 0 {
+
 		// If this is the first request, try to determine the hostname to associate
-		// with this connection.
-		if atomic.CompareAndSwapInt32(&conn.firstWrite, 1, 0) {
+		// with this connection. Skip parsing when not recording per-host bytes, as
+		// the hostname isn't used in this case.
+
+		if conn.isRecordingHostBytes() && atomic.CompareAndSwapInt32(&conn.firstWrite, 1, 0) {
 
 			hostname, ok := getHostname(buffer)
 			if ok {
@@ -86,6 +99,7 @@ func (conn *Conn) Write(buffer []byte) (n int, err error) {
 			conn.hostname,
 			int64(n),
 			0},
+			conn.isRecordingHostBytes(),
 			false)
 	}
 
@@ -110,6 +124,7 @@ func (conn *Conn) Read(buffer []byte) (n int, err error) {
 		hostname,
 		0,
 		int64(n)},
+		conn.isRecordingHostBytes(),
 		false)
 
 	return

+ 0 - 56
psiphon/tunnel.go

@@ -1312,62 +1312,6 @@ func (tunnel *Tunnel) operateTunnel(tunnelOwner TunnelOwner) {
 	// Always emit a final NoticeTotalBytesTransferred
 	NoticeTotalBytesTransferred(tunnel.serverEntry.IpAddress, totalSent, totalReceived)
 
-	// Tunnel does not have a serverContext when DisableApi is set.
-	if tunnel.serverContext != nil && !tunnel.IsDiscarded() {
-
-		// The stats for this tunnel will be reported via the next successful
-		// status request.
-
-		// Since client clocks are unreliable, we report the server's timestamp from
-		// the handshake response as the absolute tunnel start time. This time
-		// will be slightly earlier than the actual tunnel activation time, as the
-		// client has to receive and parse the response and activate the tunnel.
-
-		tunnelStartTime := tunnel.serverContext.serverHandshakeTimestamp
-
-		// For the tunnel duration calculation, we use the local clock. The start time
-		// is tunnel.establishedTime as recorded when the tunnel was established. For the
-		// end time, we do not use the current time as we may now be long past the
-		// actual termination time of the tunnel. For example, the host or device may
-		// have resumed after a long sleep (it's not clear that the monotonic clock service
-		// used to measure elapsed time will or will not stop during device sleep). Instead,
-		// we use the last data received time as the estimated tunnel end time.
-		//
-		// One potential issue with using the last received time is receiving data
-		// after an extended sleep because the device sleep occurred with data still in
-		// the OS socket read buffer. This is not expected to happen on Android, as the
-		// OS will wake a process when it has TCP data available to read. (For this reason,
-		// the actual long sleep issue is only with an idle tunnel; in this case the client
-		// is responsible for sending SSH keep alives but a device sleep will delay the
-		// golang SSH keep alive timer.)
-		//
-		// Idle tunnels will only read data when a SSH keep alive is sent. As a result,
-		// the last-received-time scheme can undercount tunnel durations by up to
-		// TUNNEL_SSH_KEEP_ALIVE_PERIOD_MAX for idle tunnels.
-
-		tunnelDuration := tunnel.conn.GetLastActivityMonotime().Sub(tunnel.establishedTime)
-
-		// tunnelDuration can be < 0 when tunnel.establishedTime is recorded after the
-		// last tunnel.conn.Read() succeeds. In that case, the last read would be the
-		// handshake response, so the tunnel had, essentially, no duration.
-		if tunnelDuration < 0 {
-			tunnelDuration = 0
-		}
-
-		err := RecordTunnelStat(
-			tunnel.serverContext.sessionId,
-			tunnel.serverContext.tunnelNumber,
-			tunnel.serverEntry.IpAddress,
-			fmt.Sprintf("%d", tunnel.establishDuration),
-			tunnelStartTime,
-			fmt.Sprintf("%d", tunnelDuration),
-			totalSent,
-			totalReceived)
-		if err != nil {
-			NoticeAlert("RecordTunnelStats failed: %s", common.ContextError(err))
-		}
-	}
-
 	if err == nil {
 		NoticeInfo("shutdown operate tunnel")