Include ProxyMetrics in BrokerServerReport and server_tunnel logs

psiphon/common/api.go

@@ -49,5 +49,8 @@ type GeoIPData struct {
 }
 
 // APIParameterLogFieldFormatter is a function that returns formatted
-// LogFields containing the given GeoIPData and APIParameters.
-type APIParameterLogFieldFormatter func(GeoIPData, APIParameters) LogFields
+// LogFields containing the given GeoIPData and APIParameters. An optional
+// log field name prefix string, when specified, should be applied to the
+// output LogFields names. When GeoIPData is the zero value, it should be
+// omitted from LogFields.
+type APIParameterLogFieldFormatter func(string, GeoIPData, APIParameters) LogFields

psiphon/common/inproxy/api.go

@@ -429,12 +429,15 @@ type BrokerServerReport struct {
 	ConnectionID                ID               `cbor:"2,keyasint,omitempty"`
 	MatchedCommonCompartments   bool             `cbor:"3,keyasint,omitempty"`
 	MatchedPersonalCompartments bool             `cbor:"4,keyasint,omitempty"`
-	ProxyNATType                NATType          `cbor:"5,keyasint,omitempty"`
-	ProxyPortMappingTypes       PortMappingTypes `cbor:"6,keyasint,omitempty"`
 	ClientNATType               NATType          `cbor:"7,keyasint,omitempty"`
 	ClientPortMappingTypes      PortMappingTypes `cbor:"8,keyasint,omitempty"`
 	ClientIP                    string           `cbor:"9,keyasint,omitempty"`
 	ProxyIP                     string           `cbor:"10,keyasint,omitempty"`
+	ProxyMetrics                *ProxyMetrics    `cbor:"11,keyasint,omitempty"`
+
+	// These legacy fields are now sent in ProxyMetrics.
+	ProxyNATType          NATType          `cbor:"5,keyasint,omitempty"`
+	ProxyPortMappingTypes PortMappingTypes `cbor:"6,keyasint,omitempty"`
 }
 
 // GetNetworkType extracts the network_type from base API metrics and returns
@@ -470,6 +473,7 @@ const (
 func (metrics *ProxyMetrics) ValidateAndGetParametersAndLogFields(
 	baseAPIParameterValidator common.APIParameterValidator,
 	formatter common.APIParameterLogFieldFormatter,
+	logFieldPrefix string,
 	geoIPData common.GeoIPData) (common.APIParameters, common.LogFields, error) {
 
 	if metrics.BaseAPIParameters == nil {
@@ -502,18 +506,18 @@ func (metrics *ProxyMetrics) ValidateAndGetParametersAndLogFields(
 		return nil, nil, errors.Tracef("invalid portmapping types: %v", metrics.PortMappingTypes)
 	}
 
-	logFields := formatter(geoIPData, baseParams)
+	logFields := formatter(logFieldPrefix, geoIPData, baseParams)
 
-	logFields["proxy_protocol_version"] = metrics.ProxyProtocolVersion
-	logFields["nat_type"] = metrics.NATType
-	logFields["port_mapping_types"] = metrics.PortMappingTypes
-	logFields["max_clients"] = metrics.MaxClients
-	logFields["connecting_clients"] = metrics.ConnectingClients
-	logFields["connected_clients"] = metrics.ConnectedClients
-	logFields["limit_upstream_bytes_per_second"] = metrics.LimitUpstreamBytesPerSecond
-	logFields["limit_downstream_bytes_per_second"] = metrics.LimitDownstreamBytesPerSecond
-	logFields["peak_upstream_bytes_per_second"] = metrics.PeakUpstreamBytesPerSecond
-	logFields["peak_downstream_bytes_per_second"] = metrics.PeakDownstreamBytesPerSecond
+	logFields[logFieldPrefix+"proxy_protocol_version"] = metrics.ProxyProtocolVersion
+	logFields[logFieldPrefix+"nat_type"] = metrics.NATType
+	logFields[logFieldPrefix+"port_mapping_types"] = metrics.PortMappingTypes
+	logFields[logFieldPrefix+"max_clients"] = metrics.MaxClients
+	logFields[logFieldPrefix+"connecting_clients"] = metrics.ConnectingClients
+	logFields[logFieldPrefix+"connected_clients"] = metrics.ConnectedClients
+	logFields[logFieldPrefix+"limit_upstream_bytes_per_second"] = metrics.LimitUpstreamBytesPerSecond
+	logFields[logFieldPrefix+"limit_downstream_bytes_per_second"] = metrics.LimitDownstreamBytesPerSecond
+	logFields[logFieldPrefix+"peak_upstream_bytes_per_second"] = metrics.PeakUpstreamBytesPerSecond
+	logFields[logFieldPrefix+"peak_downstream_bytes_per_second"] = metrics.PeakDownstreamBytesPerSecond
 
 	return baseParams, logFields, nil
 }
@@ -555,7 +559,7 @@ func (metrics *ClientMetrics) ValidateAndGetLogFields(
 		return nil, errors.Tracef("invalid portmapping types: %v", metrics.PortMappingTypes)
 	}
 
-	logFields := formatter(geoIPData, baseParams)
+	logFields := formatter("", geoIPData, baseParams)
 
 	logFields["proxy_protocol_version"] = metrics.ProxyProtocolVersion
 	logFields["nat_type"] = metrics.NATType
@@ -586,7 +590,7 @@ func (request *ProxyAnnounceRequest) ValidateAndGetParametersAndLogFields(
 	}
 
 	apiParams, logFields, err := request.Metrics.ValidateAndGetParametersAndLogFields(
-		baseAPIParameterValidator, formatter, geoIPData)
+		baseAPIParameterValidator, formatter, "", geoIPData)
 	if err != nil {
 		return nil, nil, errors.Trace(err)
 	}
@@ -772,7 +776,7 @@ func (request *ProxyAnswerRequest) ValidateAndGetLogFields(
 			"invalid select proxy protocol version: %v", request.SelectedProxyProtocolVersion)
 	}
 
-	logFields := formatter(geoIPData, common.APIParameters{})
+	logFields := formatter("", geoIPData, common.APIParameters{})
 
 	logFields["connection_id"] = request.ConnectionID
 	logFields["ice_candidate_types"] = request.ICECandidateTypes
@@ -791,7 +795,7 @@ func (request *ClientRelayedPacketRequest) ValidateAndGetLogFields(
 	formatter common.APIParameterLogFieldFormatter,
 	geoIPData common.GeoIPData) (common.LogFields, error) {
 
-	logFields := formatter(geoIPData, common.APIParameters{})
+	logFields := formatter("", geoIPData, common.APIParameters{})
 
 	logFields["connection_id"] = request.ConnectionID
 
@@ -800,38 +804,66 @@ func (request *ClientRelayedPacketRequest) ValidateAndGetLogFields(
 
 // ValidateAndGetLogFields validates the BrokerServerReport and returns
 // common.LogFields for logging.
-func (request *BrokerServerReport) ValidateAndGetLogFields() (common.LogFields, error) {
+func (report *BrokerServerReport) ValidateAndGetLogFields(
+	baseAPIParameterValidator common.APIParameterValidator,
+	formatter common.APIParameterLogFieldFormatter,
+	proxyMetricsPrefix string) (common.LogFields, error) {
 
-	if !request.ProxyNATType.IsValid() {
-		return nil, errors.Tracef("invalid proxy NAT type: %v", request.ProxyNATType)
-	}
+	// Neither ClientIP nor ProxyIP is logged.
 
-	if !request.ProxyPortMappingTypes.IsValid() {
-		return nil, errors.Tracef("invalid proxy portmapping types: %v", request.ProxyPortMappingTypes)
+	if !report.ClientNATType.IsValid() {
+		return nil, errors.Tracef("invalid client NAT type: %v", report.ClientNATType)
 	}
 
-	if !request.ClientNATType.IsValid() {
-		return nil, errors.Tracef("invalid client NAT type: %v", request.ClientNATType)
+	if !report.ClientPortMappingTypes.IsValid() {
+		return nil, errors.Tracef("invalid client portmapping types: %v", report.ClientPortMappingTypes)
 	}
 
-	if !request.ClientPortMappingTypes.IsValid() {
-		return nil, errors.Tracef("invalid client portmapping types: %v", request.ClientPortMappingTypes)
+	var logFields common.LogFields
+
+	if report.ProxyMetrics == nil {
+
+		// Backwards compatibility for reports without ProxyMetrics.
+
+		if !report.ProxyNATType.IsValid() {
+			return nil, errors.Tracef("invalid proxy NAT type: %v", report.ProxyNATType)
+		}
+
+		if !report.ProxyPortMappingTypes.IsValid() {
+			return nil, errors.Tracef("invalid proxy portmapping types: %v", report.ProxyPortMappingTypes)
+		}
+
+		logFields := common.LogFields{}
+
+		logFields["proxy_nat_type"] = report.ProxyNATType
+		logFields["proxy_port_mapping_types"] = report.ProxyPortMappingTypes
+
+	} else {
+
+		var err error
+		_, logFields, err = report.ProxyMetrics.ValidateAndGetParametersAndLogFields(
+			baseAPIParameterValidator,
+			formatter,
+			proxyMetricsPrefix,
+			common.GeoIPData{}) // Proxy GeoIP data is added by the caller.
+		if err != nil {
+			return nil, errors.Trace(err)
+		}
+
 	}
 
-	// Neither ClientIP nor ProxyIP is logged.
+	logFields["inproxy_proxy_id"] = report.ProxyID
+	logFields["inproxy_connection_id"] = report.ConnectionID
+	logFields["inproxy_matched_common_compartments"] = report.MatchedCommonCompartments
+	logFields["inproxy_matched_personal_compartments"] = report.MatchedPersonalCompartments
+	logFields["inproxy_client_nat_type"] = report.ClientNATType
+	logFields["inproxy_client_port_mapping_types"] = report.ClientPortMappingTypes
 
-	logFields := common.LogFields{}
+	// TODO:
+	// - log IPv4 vs. IPv6 information
+	// - relay and log broker transport stats, such as meek HTTP version
 
-	logFields["proxy_id"] = request.ProxyID
-	logFields["connection_id"] = request.ConnectionID
-	logFields["matched_common_compartments"] = request.MatchedCommonCompartments
-	logFields["matched_personal_compartments"] = request.MatchedPersonalCompartments
-	logFields["proxy_nat_type"] = request.ProxyNATType
-	logFields["proxy_port_mapping_types"] = request.ProxyPortMappingTypes
-	logFields["client_nat_type"] = request.ClientNATType
-	logFields["client_port_mapping_types"] = request.ClientPortMappingTypes
-
-	return common.LogFields{}, nil
+	return logFields, nil
 }
 
 func MarshalProxyAnnounceRequest(request *ProxyAnnounceRequest) ([]byte, error) {

psiphon/common/inproxy/broker.go

@@ -524,7 +524,7 @@ func (b *Broker) handleProxyAnnounce(
 	// Always log the outcome.
 	defer func() {
 		if logFields == nil {
-			logFields = b.config.APIParameterLogFieldFormatter(geoIPData, nil)
+			logFields = b.config.APIParameterLogFieldFormatter("", geoIPData, nil)
 		}
 		logFields["broker_event"] = "proxy-announce"
 		logFields["broker_id"] = b.brokerID
@@ -692,9 +692,9 @@ func (b *Broker) handleProxyAnnounce(
 				NATType:                announceRequest.Metrics.NATType,
 				PortMappingTypes:       announceRequest.Metrics.PortMappingTypes,
 			},
-			ProxyID:              initiatorID,
-			ConnectionID:         connectionID,
-			ProxyProtocolVersion: announceRequest.Metrics.ProxyProtocolVersion,
+			ProxyID:      initiatorID,
+			ProxyMetrics: announceRequest.Metrics,
+			ConnectionID: connectionID,
 		})
 	if err != nil {
 
@@ -813,7 +813,7 @@ func (b *Broker) handleClientOffer(
 	// Always log the outcome.
 	defer func() {
 		if logFields == nil {
-			logFields = b.config.APIParameterLogFieldFormatter(geoIPData, nil)
+			logFields = b.config.APIParameterLogFieldFormatter("", geoIPData, nil)
 		}
 		logFields["broker_event"] = "client-offer"
 		logFields["broker_id"] = b.brokerID
@@ -1034,7 +1034,6 @@ func (b *Broker) handleClientOffer(
 	// sent through a secure session established between the broker and the
 	// server, relayed by the client.
 	//
-
 	// The first relay message will be embedded in the Psiphon handshake. The
 	// broker may already have an established session with the server. In
 	// this case, only only that initial message is required. The
@@ -1059,12 +1058,12 @@ func (b *Broker) handleClientOffer(
 			ConnectionID:                proxyAnswer.ConnectionID,
 			MatchedCommonCompartments:   matchedCommonCompartments,
 			MatchedPersonalCompartments: matchedPersonalCompartments,
-			ProxyNATType:                proxyMatchAnnouncement.Properties.NATType,
-			ProxyPortMappingTypes:       proxyMatchAnnouncement.Properties.PortMappingTypes,
 			ClientNATType:               clientMatchOffer.Properties.NATType,
 			ClientPortMappingTypes:      clientMatchOffer.Properties.PortMappingTypes,
 			ClientIP:                    clientIP,
 			ProxyIP:                     proxyAnswer.ProxyIP,
+			ProxyMetrics:                proxyMatchAnnouncement.ProxyMetrics,
+			// ProxyMetrics includes proxy NAT and port mapping types.
 		})
 	if err != nil {
 		return nil, errors.Trace(err)
@@ -1110,7 +1109,7 @@ func (b *Broker) handleProxyAnswer(
 	// Always log the outcome.
 	defer func() {
 		if logFields == nil {
-			logFields = b.config.APIParameterLogFieldFormatter(geoIPData, nil)
+			logFields = b.config.APIParameterLogFieldFormatter("", geoIPData, nil)
 		}
 		logFields["broker_event"] = "proxy-answer"
 		logFields["broker_id"] = b.brokerID
@@ -1233,7 +1232,7 @@ func (b *Broker) handleClientRelayedPacket(
 	// Always log the outcome.
 	defer func() {
 		if logFields == nil {
-			logFields = b.config.APIParameterLogFieldFormatter(geoIPData, nil)
+			logFields = b.config.APIParameterLogFieldFormatter("", geoIPData, nil)
 		}
 		logFields["broker_event"] = "client-relayed-packet"
 		logFields["broker_id"] = b.brokerID

psiphon/common/inproxy/matcher.go

@@ -164,10 +164,10 @@ func (p *MatchProperties) IsPreferredNATMatch(
 
 // MatchAnnouncement is a proxy announcement to be queued for matching.
 type MatchAnnouncement struct {
-	Properties           MatchProperties
-	ProxyID              ID
-	ConnectionID         ID
-	ProxyProtocolVersion int32
+	Properties   MatchProperties
+	ProxyID      ID
+	ProxyMetrics *ProxyMetrics
+	ConnectionID ID
 }
 
 // MatchOffer is a client offer to be queued for matching.

psiphon/common/inproxy/server.go

@@ -36,6 +36,10 @@ const MaxRelayRoundTrips = 10
 // server by the client.
 type ServerBrokerSessions struct {
 	sessions *ResponderSessions
+
+	proxyMetricsValidator common.APIParameterValidator
+	proxyMetricsFormatter common.APIParameterLogFieldFormatter
+	proxyMetricsPrefix    string
 }
 
 // NewServerBrokerSessions create a new ServerBrokerSessions, with the
@@ -44,7 +48,10 @@ type ServerBrokerSessions struct {
 func NewServerBrokerSessions(
 	serverPrivateKey SessionPrivateKey,
 	serverRootObfuscationSecret ObfuscationSecret,
-	brokerPublicKeys []SessionPublicKey) (*ServerBrokerSessions, error) {
+	brokerPublicKeys []SessionPublicKey,
+	proxyMetricsValidator common.APIParameterValidator,
+	proxyMetricsFormatter common.APIParameterLogFieldFormatter,
+	proxyMetricsPrefix string) (*ServerBrokerSessions, error) {
 
 	sessions, err := NewResponderSessionsForKnownInitiators(
 		serverPrivateKey, serverRootObfuscationSecret, brokerPublicKeys)
@@ -54,6 +61,10 @@ func NewServerBrokerSessions(
 
 	return &ServerBrokerSessions{
 		sessions: sessions,
+
+		proxyMetricsValidator: proxyMetricsValidator,
+		proxyMetricsFormatter: proxyMetricsFormatter,
+		proxyMetricsPrefix:    proxyMetricsPrefix,
 	}, nil
 }
 
@@ -125,7 +136,8 @@ func (s *ServerBrokerSessions) HandlePacket(
 			return nil, errors.Trace(err)
 		}
 
-		logFields, err := brokerReport.ValidateAndGetLogFields()
+		logFields, err := brokerReport.ValidateAndGetLogFields(
+			s.proxyMetricsValidator, s.proxyMetricsFormatter, s.proxyMetricsPrefix)
 		if err != nil {
 			return nil, errors.Trace(err)
 		}
@@ -133,20 +145,6 @@ func (s *ServerBrokerSessions) HandlePacket(
 		// The initiatorID is the broker's public key.
 		logFields["inproxy_broker_id"] = initiatorID
 
-		logFields["inproxy_connection_id"] = brokerReport.ConnectionID
-		logFields["inproxy_proxy_id"] = brokerReport.ProxyID
-
-		// !matched_common_compartments implies a personal compartment ID match
-		logFields["inproxy_matched_common_compartments"] = brokerReport.MatchedCommonCompartments
-		logFields["inproxy_proxy_nat_type"] = brokerReport.ProxyNATType
-		logFields["inproxy_proxy_port_mapping_types"] = brokerReport.ProxyPortMappingTypes
-		logFields["inproxy_client_nat_type"] = brokerReport.ClientNATType
-		logFields["inproxy_client_port_mapping_types"] = brokerReport.ClientPortMappingTypes
-
-		// TODO:
-		// - log IPv4 vs. IPv6 information
-		// - relay and log broker transport stats, such as meek HTTP version
-
 		ok := true
 
 		// The client must supply same connection ID to server that the broker

psiphon/common/tactics/tactics.go

@@ -1364,7 +1364,7 @@ func (server *Server) handleTacticsRequest(
 	}
 	// Log a metric.
 
-	logFields := server.logFieldFormatter(geoIPData, apiParams)
+	logFields := server.logFieldFormatter("", geoIPData, apiParams)
 
 	logFields[NEW_TACTICS_TAG_LOG_FIELD_NAME] = tacticsPayload.Tag
 	logFields[IS_TACTICS_REQUEST_LOG_FIELD_NAME] = true

psiphon/server/api.go

@@ -318,6 +318,7 @@ func handshakeAPIRequestHandler(
 
 	if IsLogLevelDebug() {
 		logFields := getRequestLogFields(
+			"",
 			"",
 			sshClient.sessionID,
 			clientGeoIPData,
@@ -625,6 +626,7 @@ func connectedAPIRequestHandler(
 		log.LogRawFieldsWithTimestamp(
 			getRequestLogFields(
 				"unique_user",
+				"",
 				sshClient.sessionID,
 				sshClient.getClientGeoIPData(),
 				authorizedAccessTypes,
@@ -755,6 +757,7 @@ func statusAPIRequestHandler(
 
 			domainBytesFields := getRequestLogFields(
 				"domain_bytes",
+				"",
 				sshClient.sessionID,
 				sshClient.getClientGeoIPData(),
 				authorizedAccessTypes,
@@ -800,6 +803,7 @@ func statusAPIRequestHandler(
 
 			remoteServerListFields := getRequestLogFields(
 				"remote_server_list",
+				"",
 				"", // Use the session_id the client recorded with the event
 				sshClient.getClientGeoIPData(),
 				authorizedAccessTypes,
@@ -841,6 +845,7 @@ func statusAPIRequestHandler(
 
 			failedTunnelFields := getRequestLogFields(
 				"failed_tunnel",
+				"",
 				"", // Use the session_id the client recorded with the event
 				sshClient.getClientGeoIPData(),
 				authorizedAccessTypes,
@@ -953,10 +958,11 @@ func getTacticsAPIParameterValidator(config *Config) common.APIParameterValidato
 
 func getTacticsAPIParameterLogFieldFormatter() common.APIParameterLogFieldFormatter {
 
-	return func(geoIPData common.GeoIPData, params common.APIParameters) common.LogFields {
+	return func(prefix string, geoIPData common.GeoIPData, params common.APIParameters) common.LogFields {
 
 		logFields := getRequestLogFields(
 			tactics.TACTICS_METRIC_EVENT_NAME,
+			prefix,
 			"", // Use the session_id the client reported
 			GeoIPData(geoIPData),
 			nil, // authorizedAccessTypes are not known yet
@@ -983,10 +989,11 @@ func getInproxyBrokerAPIParameterValidator(config *Config) common.APIParameterVa
 
 func getInproxyBrokerAPIParameterLogFieldFormatter() common.APIParameterLogFieldFormatter {
 
-	return func(geoIPData common.GeoIPData, params common.APIParameters) common.LogFields {
+	return func(prefix string, geoIPData common.GeoIPData, params common.APIParameters) common.LogFields {
 
 		logFields := getRequestLogFields(
 			"inproxy_broker",
+			prefix,
 			"", // Use the session_id the client reported
 			GeoIPData(geoIPData),
 			nil,
@@ -997,6 +1004,23 @@ func getInproxyBrokerAPIParameterLogFieldFormatter() common.APIParameterLogField
 	}
 }
 
+func getInproxyBrokerServerReportParameterLogFieldFormatter() common.APIParameterLogFieldFormatter {
+
+	return func(prefix string, _ common.GeoIPData, params common.APIParameters) common.LogFields {
+
+		logFields := getRequestLogFields(
+			"",
+			prefix,
+			"",          // Use the session_id in ProxyMetrics
+			GeoIPData{}, // Proxy GeoIP data is added in sshClient.logTunnel
+			nil,
+			params,
+			inproxyBrokerRequestParams)
+
+		return common.LogFields(logFields)
+	}
+}
+
 // requestParamSpec defines a request parameter. Each param is expected to be
 // a string, unless requestParamArray is specified, in which case an array of
 // strings is expected.
@@ -1267,8 +1291,10 @@ func validateStringArrayRequestParam(
 
 // getRequestLogFields makes LogFields to log the API event following
 // the legacy psi_web and current ELK naming conventions.
+// When GeoIPData is the zero value, it is omitted.
 func getRequestLogFields(
 	eventName string,
+	logFieldPrefix string,
 	sessionID string,
 	geoIPData GeoIPData,
 	authorizedAccessTypes []string,
@@ -1293,7 +1319,10 @@ func getRequestLogFields(
 		logFields["event_name"] = eventName
 	}
 
-	geoIPData.SetClientLogFields(logFields)
+	zeroGeoIPData := GeoIPData{}
+	if geoIPData != zeroGeoIPData {
+		geoIPData.SetClientLogFields(logFields)
+	}
 
 	if len(authorizedAccessTypes) > 0 {
 		logFields["authorized_access_types"] = authorizedAccessTypes
@@ -1351,6 +1380,11 @@ func getRequestLogFields(
 			}
 		}
 
+		name := expectedParam.name
+		if logFieldPrefix != "" {
+			name = logFieldPrefix + name
+		}
+
 		switch v := value.(type) {
 		case string:
 			strValue := v
@@ -1367,14 +1401,18 @@ func getRequestLogFields(
 			case "meek_dial_address":
 				host, _, _ := net.SplitHostPort(strValue)
 				if isIPAddress(nil, host) {
-					logFields["meek_dial_ip_address"] = host
+					name = "meek_dial_ip_address"
 				} else {
-					logFields["meek_dial_domain"] = host
+					name = "meek_dial_domain"
+				}
+				if logFieldPrefix != "" {
+					name = logFieldPrefix + name
 				}
+				logFields[name] = host
 
 			case "upstream_proxy_type":
 				// Submitted value could be e.g., "SOCKS5" or "socks5"; log lowercase
-				logFields[expectedParam.name] = strings.ToLower(strValue)
+				logFields[name] = strings.ToLower(strValue)
 
 			case tactics.SPEED_TEST_SAMPLES_PARAMETER_NAME:
 				// Due to a client bug, clients may deliever an incorrect ""
@@ -1392,44 +1430,44 @@ func getRequestLogFields(
 				if index != -1 {
 					strValue = strValue[:index+len(target)] + "<redacted>"
 				}
-				logFields[expectedParam.name] = strValue
+				logFields[name] = strValue
 
 			default:
 				if expectedParam.flags&requestParamLogStringAsInt != 0 {
 					intValue, _ := strconv.Atoi(strValue)
-					logFields[expectedParam.name] = intValue
+					logFields[name] = intValue
 
 				} else if expectedParam.flags&requestParamLogStringAsFloat != 0 {
 					floatValue, _ := strconv.ParseFloat(strValue, 64)
-					logFields[expectedParam.name] = floatValue
+					logFields[name] = floatValue
 
 				} else if expectedParam.flags&requestParamLogStringLengthAsInt != 0 {
-					logFields[expectedParam.name] = len(strValue)
+					logFields[name] = len(strValue)
 
 				} else if expectedParam.flags&requestParamLogFlagAsBool != 0 {
 					// Submitted value could be "0" or "1"
 					// "0" and non "0"/"1" values should be transformed to false
 					// "1" should be transformed to true
 					if strValue == "1" {
-						logFields[expectedParam.name] = true
+						logFields[name] = true
 					} else {
-						logFields[expectedParam.name] = false
+						logFields[name] = false
 					}
 
 				} else {
-					logFields[expectedParam.name] = strValue
+					logFields[name] = strValue
 				}
 			}
 
 		case []interface{}:
 			if expectedParam.name == tactics.SPEED_TEST_SAMPLES_PARAMETER_NAME {
-				logFields[expectedParam.name] = makeSpeedTestSamplesLogField(v)
+				logFields[name] = makeSpeedTestSamplesLogField(v)
 			} else {
-				logFields[expectedParam.name] = v
+				logFields[name] = v
 			}
 
 		default:
-			logFields[expectedParam.name] = v
+			logFields[name] = v
 		}
 	}
 

psiphon/server/server_test.go

@@ -681,7 +681,11 @@ var (
 	testUserAgents                       = []string{"ua1", "ua2", "ua3"}
 	testNetworkType                      = "WIFI"
 	testCustomHostNameRegex              = `[a-z0-9]{5,10}\.example\.org`
+	testClientVersion                    = 1
+	testClientPlatform                   = "Android_10_com.test.app"
 	testClientFeatures                   = []string{"feature 1", "feature 2"}
+	testDeviceRegion                     = "US"
+	testDeviceLocation                   = "gzzzz"
 	testDisallowedTrafficAlertActionURLs = []string{"https://example.org/disallowed"}
 
 	// A steering IP must not be a bogon; this address is not dialed.
@@ -1229,13 +1233,13 @@ func runServer(t *testing.T, runConfig *runServerConfig) {
 
 	clientConfigJSON := fmt.Sprintf(`
     {
-        "ClientPlatform" : "Android_10_com.test.app",
-        "ClientVersion" : "0",
+        "ClientVersion" : "%d",
+        "ClientPlatform" : "%s",
         "ClientFeatures" : %s,
         "SponsorId" : "0000000000000000",
         "PropagationChannelId" : "0000000000000000",
-        "DeviceLocation" : "gzzzz",
-        "DeviceRegion" : "US",
+        "DeviceRegion" : "%s",
+        "DeviceLocation" : "%s",
         "DisableRemoteServerListFetcher" : true,
         "EstablishTunnelPausePeriodSeconds" : 1,
         "ConnectionWorkerPoolSize" : %d,
@@ -1243,7 +1247,11 @@ func runServer(t *testing.T, runConfig *runServerConfig) {
         %s
         %s
     }`,
+		testClientVersion,
+		testClientPlatform,
 		string(testClientFeaturesJSON),
+		testDeviceRegion,
+		testDeviceLocation,
 		numTunnels,
 		clientTunnelProtocol,
 		jsonLimitTLSProfiles,
@@ -1809,6 +1817,8 @@ func runServer(t *testing.T, runConfig *runServerConfig) {
 	case logFields := <-serverTunnelLog:
 		err := checkExpectedServerTunnelLogFields(
 			runConfig,
+			propagationChannelID,
+			sponsorID,
 			doClientTactics,
 			expectClientBPFField,
 			expectServerBPFField,
@@ -2064,6 +2074,8 @@ func (c *networkConnectivityChecker) HasNetworkConnectivity() int {
 
 func checkExpectedServerTunnelLogFields(
 	runConfig *runServerConfig,
+	expectPropagationChannelID string,
+	expectSponsorID string,
 	expectAppliedTacticsTag bool,
 	expectClientBPFField bool,
 	expectServerBPFField bool,
@@ -2095,6 +2107,7 @@ func checkExpectedServerTunnelLogFields(
 		"establishment_duration",
 		"propagation_channel_id",
 		"sponsor_id",
+		"client_version",
 		"client_platform",
 		"client_features",
 		"relay_protocol",
@@ -2131,20 +2144,20 @@ func checkExpectedServerTunnelLogFields(
 		return fmt.Errorf("unexpected host_id '%s'", fields["host_id"])
 	}
 
-	tunnelProtocol := runConfig.tunnelProtocol
-	if runConfig.clientTunnelProtocol != "" {
-		// In cases such as UNFRONTED-HTTPS-OSSH/TLS-OSSH demux,
-		// runConfig.tunnelProtocol is the server listening protocol and
-		// runConfig.clientTunnelProtocol is the actual tunnel protocol.
-		tunnelProtocol = runConfig.clientTunnelProtocol
+	if fields["propagation_channel_id"].(string) != expectPropagationChannelID {
+		return fmt.Errorf("unexpected propagation_channel_id '%s'", fields["propagation_channel_id"])
 	}
 
-	if fields["relay_protocol"].(string) != tunnelProtocol {
-		return fmt.Errorf("unexpected relay_protocol '%s'", fields["relay_protocol"])
+	if fields["sponsor_id"].(string) != expectSponsorID {
+		return fmt.Errorf("unexpected sponsor_id '%s'", fields["sponsor_id"])
 	}
 
-	if !common.Contains(testSSHClientVersions, fields["ssh_client_version"].(string)) {
-		return fmt.Errorf("unexpected ssh_client_version '%s'", fields["ssh_client_version"])
+	if int(fields["client_version"].(float64)) != testClientVersion {
+		return fmt.Errorf("unexpected client_version '%s'", fields["client_version"])
+	}
+
+	if fields["client_platform"].(string) != testClientPlatform {
+		return fmt.Errorf("unexpected client_platform '%s'", fields["client_platform"])
 	}
 
 	clientFeatures := fields["client_features"].([]interface{})
@@ -2157,6 +2170,22 @@ func checkExpectedServerTunnelLogFields(
 		}
 	}
 
+	tunnelProtocol := runConfig.tunnelProtocol
+	if runConfig.clientTunnelProtocol != "" {
+		// In cases such as UNFRONTED-HTTPS-OSSH/TLS-OSSH demux,
+		// runConfig.tunnelProtocol is the server listening protocol and
+		// runConfig.clientTunnelProtocol is the actual tunnel protocol.
+		tunnelProtocol = runConfig.clientTunnelProtocol
+	}
+
+	if fields["relay_protocol"].(string) != tunnelProtocol {
+		return fmt.Errorf("unexpected relay_protocol '%s'", fields["relay_protocol"])
+	}
+
+	if !common.Contains(testSSHClientVersions, fields["ssh_client_version"].(string)) {
+		return fmt.Errorf("unexpected ssh_client_version '%s'", fields["ssh_client_version"])
+	}
+
 	if fields["network_type"].(string) != testNetworkType {
 		return fmt.Errorf("unexpected network_type '%s'", fields["network_type"])
 	}
@@ -2430,9 +2459,30 @@ func checkExpectedServerTunnelLogFields(
 			"inproxy_connection_id",
 			"inproxy_proxy_id",
 			"inproxy_matched_common_compartments",
-			"inproxy_proxy_nat_type",
 			"inproxy_client_nat_type",
 
+			"inproxy_proxy_propagation_channel_id",
+			"inproxy_proxy_sponsor_id",
+			"inproxy_proxy_client_version",
+			"inproxy_proxy_client_platform",
+			"inproxy_proxy_client_features",
+			"inproxy_proxy_device_region",
+			"inproxy_proxy_device_location",
+			"inproxy_proxy_network_type",
+			"inproxy_proxy_proxy_protocol_version",
+			"inproxy_proxy_nat_type",
+			"inproxy_proxy_max_clients",
+			"inproxy_proxy_connecting_clients",
+			"inproxy_proxy_connected_clients",
+			"inproxy_proxy_limit_upstream_bytes_per_second",
+			"inproxy_proxy_limit_downstream_bytes_per_second",
+			"inproxy_proxy_peak_upstream_bytes_per_second",
+			"inproxy_proxy_peak_downstream_bytes_per_second",
+
+			// These ProxyMetrics fields are not populated in this test:
+			// "inproxy_proxy_client_build_rev",
+			// "inproxy_proxy_port_mapping_types",
+
 			// Fields sent by the client
 
 			"inproxy_broker_transport",
@@ -2465,6 +2515,52 @@ func checkExpectedServerTunnelLogFields(
 		if fields["inproxy_broker_fronting_provider_id"].(string) != inproxyTestConfig.brokerFrontingProviderID {
 			return fmt.Errorf("unexpected inproxy_broker_fronting_provider_id '%s'", fields["inproxy_broker_fronting_provider_id"])
 		}
+
+		// Check some fields from ProxyMetrics. Since the proxy and client are
+		// the same tunnel core instance, fields such as session_id are the
+		// same for both the client and the proxy.
+
+		if fields["inproxy_proxy_session_id"].(string) != fields["session_id"].(string) {
+			return fmt.Errorf("unexpected inproxy_proxy_session_id '%s'", fields["session_id"])
+		}
+
+		if fields["inproxy_proxy_propagation_channel_id"].(string) != expectPropagationChannelID {
+			return fmt.Errorf("unexpected inproxy_proxy_propagation_channel_id '%s'", fields["inproxy_proxy_propagation_channel_id"])
+		}
+
+		if fields["inproxy_proxy_sponsor_id"].(string) != expectSponsorID {
+			return fmt.Errorf("unexpected inproxy_proxy_sponsor_id '%s'", fields["inproxy_proxy_sponsor_id"])
+		}
+
+		if int(fields["inproxy_proxy_client_version"].(float64)) != testClientVersion {
+			return fmt.Errorf("unexpected inproxy_proxy_client_version '%s'", fields["inproxy_proxy_client_version"])
+		}
+
+		if fields["inproxy_proxy_client_platform"].(string) != testClientPlatform {
+			return fmt.Errorf("unexpected inproxy_proxy_client_platform '%s'", fields["inproxy_proxy_client_platform"])
+		}
+
+		clientFeatures := fields["inproxy_proxy_client_features"].([]interface{})
+		if len(clientFeatures) != len(testClientFeatures) {
+			return fmt.Errorf("unexpected inproxy_proxy_client_features '%s'", fields["inproxy_proxy_client_features"])
+		}
+		for i, feature := range testClientFeatures {
+			if clientFeatures[i].(string) != feature {
+				return fmt.Errorf("unexpected inproxy_proxy_client_features '%s'", fields["inproxy_proxy_client_features"])
+			}
+		}
+
+		if fields["inproxy_proxy_device_region"].(string) != testDeviceRegion {
+			return fmt.Errorf("unexpected inproxy_proxy_device_region '%s'", fields["inproxy_proxy_device_region"])
+		}
+
+		if fields["inproxy_proxy_device_location"].(string) != testDeviceLocation {
+			return fmt.Errorf("unexpected inproxy_proxy_device_location '%s'", fields["inproxy_proxy_device_location"])
+		}
+
+		if fields["inproxy_proxy_network_type"].(string) != testNetworkType {
+			return fmt.Errorf("unexpected inproxy_proxy_network_type '%s'", fields["inproxy_proxy_network_type"])
+		}
 	}
 
 	if runConfig.applyPrefix {

psiphon/server/tunnelServer.go

@@ -455,7 +455,12 @@ func newSSHServer(
 		// The expected broker public keys are set in reloadTactics directly
 		// below, so none are set here.
 		inproxyBrokerSessions, err = inproxy.NewServerBrokerSessions(
-			inproxyPrivateKey, inproxyObfuscationSecret, nil)
+			inproxyPrivateKey,
+			inproxyObfuscationSecret,
+			nil,
+			getInproxyBrokerAPIParameterValidator(support.Config),
+			getInproxyBrokerAPIParameterLogFieldFormatter(),
+			"inproxy_proxy_") // Prefix for proxy metrics log fields in server_tunnel
 		if err != nil {
 			return nil, errors.Trace(err)
 		}
@@ -3304,6 +3309,7 @@ func (sshClient *sshClient) logTunnel(additionalMetrics []LogFields) {
 
 	logFields := getRequestLogFields(
 		"server_tunnel",
+		"",
 		sshClient.sessionID,
 		sshClient.clientGeoIPData,
 		sshClient.handshakeState.authorizedAccessTypes,
@@ -3472,6 +3478,7 @@ func (sshClient *sshClient) logBlocklistHits(IP net.IP, domain string, tags []Bl
 
 	logFields := getRequestLogFields(
 		"server_blocklist_hit",
+		"",
 		sshClient.sessionID,
 		sshClient.clientGeoIPData,
 		sshClient.handshakeState.authorizedAccessTypes,